From ad9603ad53db661f723332077af12c28b01f1c58 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 10:23:57 +0200 Subject: [PATCH 1/8] Add concurrent-user stress test harness MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds tooling to test the live system at ~20 simultaneous users, targeting the production Pages origin so requests pass through the Pages Function and its service binding — the path where Pyodide cold-start 500s appear. The Worker origin bypasses it and cannot reproduce them. - backend/scripts/seed_load_test_users.py seeds loadtest-NN@example.com accounts directly in D1. Going through /api/auth/register would take four hours at the 5/hour registration limit. Password comes from LOADTEST_PASSWORD, never the repo; generated SQL and session files are gitignored. - load-test/build-scenario.mjs derives the replayed request sequence from sessionStorage['studyplanner:api-request-log'], which the app already keeps, rather than hand-writing an assumed sequence. It excludes login, register, logout, feedback and client-errors, each of which is rate limited per IP or would break the session. - load-test/mint-sessions.mjs collects session cookies out of band, pacing to the fixed 15-minute login window. Logging in inside the test would hit the 10/15min limit at VU 11 and measure the limiter instead of the app. - load-test/scenario.js replays at 20 VUs with think time, failing the run on any 5xx or 429. - load-test/login-burst.js times 8 simultaneous logins (PBKDF2 at 310k iterations in Pyodide) with headroom under the limit. docs/load-test-2026-08.md records the one finding that needed no load run: enforce_rate_limit keys on the client IP, so 20 users behind one campus NAT share a 10-logins-per-15-minutes budget and users 11-20 get 429. Co-Authored-By: Claude Opus 5 --- .gitignore | 6 + CLAUDE.md | 3 + backend/scripts/seed_load_test_users.py | 220 ++++++++++++++++++++++++ docs/load-test-2026-08.md | 107 ++++++++++++ load-test/README.md | 169 ++++++++++++++++++ load-test/build-scenario.mjs | 113 ++++++++++++ load-test/login-burst.js | 71 ++++++++ load-test/mint-sessions.mjs | 152 ++++++++++++++++ load-test/recorded-session.json | 19 ++ load-test/scenario.js | 215 +++++++++++++++++++++++ 10 files changed, 1075 insertions(+) create mode 100644 backend/scripts/seed_load_test_users.py create mode 100644 docs/load-test-2026-08.md create mode 100644 load-test/README.md create mode 100644 load-test/build-scenario.mjs create mode 100644 load-test/login-burst.js create mode 100644 load-test/mint-sessions.mjs create mode 100644 load-test/recorded-session.json create mode 100644 load-test/scenario.js diff --git a/.gitignore b/.gitignore index 4cb5456..92a744c 100644 --- a/.gitignore +++ b/.gitignore @@ -249,3 +249,9 @@ __marimo__/ # Generated D1 seed chunk files (backend/scripts/import_alma_json_to_d1.py) backend/data/seed_chunks/ + +# Stress-test harness (load-test/README.md). +# Generated account credentials and live session cookies must never be committed. +backend/data/seed_load_test_users.sql +load-test/sessions.json +load-test/results/ diff --git a/CLAUDE.md b/CLAUDE.md index 0d2d1d8..9cc6856 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -40,6 +40,9 @@ Deliver a prioritized list: file, issue, and why it matters. `debug-onboarding-*@example.com` (e.g. `debug-onboarding-1781713357@example.com`). They are intentionally kept (not deleted) for future debugging. Ignore them in user counts; remove with an explicit `DELETE ... WHERE username = ''` only if asked. +- Stress-test accounts follow the same rule under `loadtest-NN@example.com`, seeded by + `backend/scripts/seed_load_test_users.py`. They are retained between runs (sessions stay + valid 30 days) and must also be ignored in user counts. See `load-test/README.md`. ## Course catalog data (ALMA scraper → D1) diff --git a/backend/scripts/seed_load_test_users.py b/backend/scripts/seed_load_test_users.py new file mode 100644 index 0000000..e3b8a74 --- /dev/null +++ b/backend/scripts/seed_load_test_users.py @@ -0,0 +1,220 @@ +"""Seed the `loadtest-*` accounts used by the concurrent-user stress test. + + py backend/scripts/seed_load_test_users.py --count 20 # dry run + py backend/scripts/seed_load_test_users.py --count 20 --apply # write to D1 + +The password is never stored in the repo: set LOADTEST_PASSWORD in the +environment before running. The same value must be passed to the k6 harness +(see load-test/README.md). + +Why seed through SQL instead of POSTing /api/auth/register: +AUTH_REGISTRATION_POLICY in backend/src/services/request_rate_limit.py allows 5 +registrations per hour per client IP, so creating 20 accounts through the API +from one machine would take four hours. + +The rows this writes mirror what register_user() in +backend/src/services/authentication.py produces: + + * user_auth — username/email/password_hash/password_salt. The hash format is + PBKDF2-HMAC-SHA256 at PASSWORD_PBKDF2_ITERATIONS, hex-encoded, exactly as + _hash_password() computes it. If that constant ever changes, logins for + these accounts break until this script is re-run. + * user_state — display name plus the supported PO 2021 study program and its + default regulation version, resolved by subselect. login_user() would + backfill a bare user_state row on its own, but seeding the study program + matters: without it /api/me/progress short-circuits and the stress test + would exercise a much cheaper query path than a real account does. + +user_progress is left to ensure_user_progress() on first login. + +Re-running is safe: user_auth rows are upserted (so a password change is just a +re-run) and user_state rows use INSERT OR IGNORE so an account that has since +accumulated planner data is never reset. + +These accounts are intentionally retained after a test run, like the +debug-onboarding-* accounts described in CLAUDE.md. Exclude them from user +counts. +""" + +from __future__ import annotations + +import argparse +import hashlib +import os +import secrets +import subprocess +import sys +import time +from pathlib import Path + +ROOT_DIR = Path(__file__).resolve().parents[1] +DEFAULT_OUT_SQL = ROOT_DIR / "data" / "seed_load_test_users.sql" +DEFAULT_DB_NAME = "studyplanner-db" +DEFAULT_COUNT = 20 +DEFAULT_ACCOUNT_TEMPLATE = "loadtest-{index:02d}@example.com" + +# Must stay in sync with PASSWORD_PBKDF2_ITERATIONS in +# backend/src/services/authentication.py — a mismatch produces accounts that +# exist but can never log in. +PASSWORD_PBKDF2_ITERATIONS = 310_000 + +# Mirrors SUPPORTED_REGULATION_SOURCE_STATUS / SUPPORTED_REGULATION_PO_VERSION. +SUPPORTED_SOURCE_STATUS = "official" +SUPPORTED_PO_VERSION = "2021" + + +def hash_password(password: str, salt_hex: str) -> str: + """Hash exactly as authentication._hash_password does.""" + password_hash = hashlib.pbkdf2_hmac( + "sha256", + password.encode("utf-8"), + bytes.fromhex(salt_hex), + PASSWORD_PBKDF2_ITERATIONS, + ) + return password_hash.hex() + + +def sql_quote(value: str) -> str: + return "'" + value.replace("'", "''") + "'" + + +def build_account_usernames(count: int, template: str) -> list[str]: + if count < 1: + raise ValueError("count must be at least 1") + return [template.format(index=index) for index in range(1, count + 1)] + + +def build_seed_sql(usernames: list[str], password: str, now_unix: int) -> str: + """Return idempotent SQL creating one credential + state row per account.""" + statements: list[str] = [ + "-- Generated by backend/scripts/seed_load_test_users.py — do not edit by hand.", + "-- Stress-test accounts; see load-test/README.md.", + "", + ] + + for username in usernames: + salt_hex = secrets.token_hex(16) + password_hash = hash_password(password, salt_hex) + quoted_username = sql_quote(username) + statements.append( + "INSERT INTO user_auth (" + "username, email, password_hash, password_salt, created_at_unix, updated_at_unix" + ") VALUES (" + f"{quoted_username}, {quoted_username}, " + f"{sql_quote(password_hash)}, {sql_quote(salt_hex)}, {now_unix}, {now_unix}" + ") ON CONFLICT(username) DO UPDATE SET " + "password_hash = excluded.password_hash, " + "password_salt = excluded.password_salt, " + "updated_at_unix = excluded.updated_at_unix;" + ) + + statements.append("") + + for username in usernames: + quoted_username = sql_quote(username) + display_name = sql_quote(username.split("@", 1)[0]) + statements.append( + "INSERT OR IGNORE INTO user_state (" + "username, display_name, created_at_unix, updated_at_unix" + f") VALUES ({quoted_username}, {display_name}, {now_unix}, {now_unix});" + ) + + statements.append("") + + # The study program is attached in two follow-up UPDATEs rather than inline + # in each INSERT, so each subselect is written once instead of once per + # account. Both are guarded by `IS NULL`, so re-running never overwrites a + # program an account has since been given. + username_list = ", ".join(sql_quote(username) for username in usernames) + official = sql_quote(SUPPORTED_SOURCE_STATUS) + po_version = sql_quote(SUPPORTED_PO_VERSION) + + # Resolved by subselect rather than a hardcoded id so this keeps working + # after a catalog re-seed renumbers study_programs. + statements.append( + "UPDATE user_state SET study_program_id = (" + "SELECT sp.id FROM study_programs AS sp" + " JOIN study_program_regulation_versions AS sprv" + " ON sprv.study_program_id = sp.id AND sprv.is_default = 1" + " JOIN regulation_versions AS rv ON rv.id = sprv.regulation_version_id" + f" WHERE sp.source_status = {official} AND sp.po_version = {po_version}" + f" AND rv.source_status = {official} AND rv.version_label = {po_version}" + " ORDER BY sp.id LIMIT 1" + f") WHERE username IN ({username_list}) AND study_program_id IS NULL;" + ) + statements.append( + "UPDATE user_state SET regulation_version_id = (" + "SELECT sprv.regulation_version_id FROM study_program_regulation_versions AS sprv" + " JOIN regulation_versions AS rv ON rv.id = sprv.regulation_version_id" + " WHERE sprv.study_program_id = user_state.study_program_id" + " AND sprv.is_default = 1" + f" AND rv.source_status = {official} AND rv.version_label = {po_version}" + " LIMIT 1" + f") WHERE username IN ({username_list}) AND regulation_version_id IS NULL;" + ) + + statements.append("") + return "\n".join(statements) + + +def wrangler_d1_execute_file(db_name: str, sql_path: Path, *, remote: bool) -> None: + target = "--remote" if remote else "--local" + print(f"[wrangler] executing {sql_path} on '{db_name}' {target} ...") + result = subprocess.run( + ["wrangler", "d1", "execute", db_name, target, "--file", str(sql_path)], + cwd=ROOT_DIR, text=True, shell=True, + stdin=subprocess.DEVNULL, encoding="utf-8", errors="replace", + ) + if result.returncode != 0: + raise SystemExit(f"wrangler d1 execute failed (exit {result.returncode})") + + +def parse_arguments() -> argparse.Namespace: + parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("--count", type=int, default=DEFAULT_COUNT, + help=f"Number of accounts to seed (default {DEFAULT_COUNT}).") + parser.add_argument("--account-template", default=DEFAULT_ACCOUNT_TEMPLATE, + help="Username/email template; must contain {index}.") + parser.add_argument("--out-sql", type=Path, default=DEFAULT_OUT_SQL, + help="Where to write the generated SQL.") + parser.add_argument("--db-name", default=DEFAULT_DB_NAME, + help=f"D1 database name (default {DEFAULT_DB_NAME}).") + parser.add_argument("--local", action="store_true", + help="Target the local D1 simulator instead of --remote.") + parser.add_argument("--apply", action="store_true", + help="Actually execute the SQL. Without it the script only writes the file.") + return parser.parse_args() + + +def main() -> None: + args = parse_arguments() + + password = os.environ.get("LOADTEST_PASSWORD", "").strip() + if not password: + raise SystemExit( + "LOADTEST_PASSWORD is not set. Choose a throwaway password and export it, " + "e.g. $env:LOADTEST_PASSWORD = '' — it is never stored in the repo." + ) + + usernames = build_account_usernames(args.count, args.account_template) + print(f"[seed] hashing {len(usernames)} passwords at {PASSWORD_PBKDF2_ITERATIONS:,} PBKDF2 iterations ...") + seed_sql = build_seed_sql(usernames, password, int(time.time())) + + args.out_sql.parent.mkdir(parents=True, exist_ok=True) + args.out_sql.write_text(seed_sql, encoding="utf-8") + print(f"[seed] wrote {args.out_sql} ({len(usernames)} accounts: {usernames[0]} .. {usernames[-1]})") + + if not args.apply: + target = "--local" if args.local else "--remote" + print("[seed] dry run — nothing executed. To apply:") + print(f" wrangler d1 execute {args.db_name} {target} --file {args.out_sql}") + return + + wrangler_d1_execute_file(args.db_name, args.out_sql, remote=not args.local) + print("[seed] done. Verify with:") + print(f" wrangler d1 execute {args.db_name} {'--local' if args.local else '--remote'} " + f"--command \"SELECT COUNT(*) FROM user_auth WHERE username LIKE 'loadtest-%'\"") + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md new file mode 100644 index 0000000..366ccb1 --- /dev/null +++ b/docs/load-test-2026-08.md @@ -0,0 +1,107 @@ +# Load test: ~20 concurrent users (August 2026) + +Report for the concurrent-user stress test. The harness and the reasoning behind +its design live in [`load-test/README.md`](../load-test/README.md). + +| | | +| --- | --- | +| Target | `https://studyplaner.pages.dev` (production Pages origin) | +| Backend | Worker `studyplanner-api`, D1 `studyplanner-db` | +| Harness | k6 (standalone binary, not an npm dependency) | +| Accounts | `loadtest-01@example.com` … `loadtest-20@example.com` | + +## Status + +| Phase | What it establishes | Status | +| --- | --- | --- | +| A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | **Confirmed by code reading; live check pending** | +| B — baseline | Uncontended per-endpoint latency | Not run | +| C — 20 concurrent users | 5xx under isolate fan-out; p95 under load | Not run | +| D — login burst | How CPU-bound logins queue | Not run | + +Phases B–D need the one-time setup in the harness README (seed accounts, record +a session, mint sessions). Until then `load-test/recorded-session.json` is a +placeholder derived from `frontend/src`, not a real recording. + +--- + +## Phase A — shared-IP rate limiting + +**This is the most likely real-world failure of the "20 users at once" scenario, +and it needs no load generator.** + +`enforce_rate_limit` keys every policy on a hash of the client IP +([`request_rate_limit.py:36`](../backend/src/services/request_rate_limit.py)): + +```python +client_ip = get_request_header(request, 'CF-Connecting-IP') or 'unknown' +return hashlib.sha256(client_ip.encode('utf-8')).hexdigest() +``` + +The policies ([`:19-23`](../backend/src/services/request_rate_limit.py)): + +| Scope | Limit | Consequence for 20 users on one egress IP | +| --- | --- | --- | +| `auth_login` | 10 / 15 min | Users 11–20 get `429` and cannot sign in | +| `auth_registration` | 5 / hour | Only 5 people per hour can create an account | +| `ai_catalog` | 30 / min | Shared across everyone on that IP | +| `client_error` | 30 / hour | Error reports silently dropped for later users | +| `feedback` | 5 / hour | Shared across everyone on that IP | + +Twenty students in one lecture hall on eduroam, or any campus NAT, present a +single `CF-Connecting-IP`. The limiter cannot distinguish them from one abusive +client. + +The window is fixed rather than rolling — `now - (now % window_seconds)` +([`:40`](../backend/src/services/request_rate_limit.py)) — so the budget resets +on wall-clock boundaries, not per user. + +**Live verification (pending):** confirm `CF-Connecting-IP` survives the Pages +service binding by issuing 11 logins from one IP and checking that the 11th +returns `429`. If it does not, the limiter is keying on `'unknown'` for every +request, which is a different and more severe problem — one global bucket for +all users. + +**Fix (out of scope here, separate branch):** key `auth_login` on the submitted +identifier, or on identifier+IP, so one account's failed attempts cannot lock +out everyone sharing an egress IP. + +--- + +## Phase B — baseline + +_Not run. Record here: single-VU per-endpoint p50, and a single cold login +timing (PBKDF2 at 310,000 iterations inside Pyodide, +[`authentication.py:15`](../backend/src/services/authentication.py))._ + +## Phase C — 20 concurrent users + +_Not run. Record here: raw k6 summary, per-endpoint p50/p95/p99, every 5xx with +the matching `wrangler tail` output, and whether the canary browser stayed +usable._ + +Expected pressure points, from reading the code: + +- `/api/me/progress` issues ~7 sequential D1 queries + ([`progress.py`](../backend/src/services/progress.py)); the catalog service + ~19. Latency is additive per request and D1 has one primary region. +- Authenticated requests bypass the Pages `caches.default` layer that serves + anonymous `GET /api/catalog/*` + ([`proxy.ts:65`](../frontend/functions/_shared/proxy.ts)), so every step here + reaches the Worker. +- Pyodide init on cold isolates is the suspected source of the previously + observed production 500s. + +## Phase D — login burst + +_Not run. Record here: 8 simultaneous login timings, and whether they serialise._ + +--- + +## Notes + +- Runs write to the production D1. Writes are confined to the `loadtest-*` + accounts' own semester plans; `/api/feedback` and `/api/client-errors` are + excluded from the scenario. +- The `loadtest-*` accounts are retained after runs, like `debug-onboarding-*`. + Exclude both from user counts. diff --git a/load-test/README.md b/load-test/README.md new file mode 100644 index 0000000..7683711 --- /dev/null +++ b/load-test/README.md @@ -0,0 +1,169 @@ +# Concurrent-user stress test + +Runbook for testing StudyPlanner at ~20 simultaneous users. Findings from each +run go in `docs/load-test-.md`. + +## What this measures, and why it looks like this + +Three risks motivated this harness. Only two need a load generator: + +1. **Shared-IP rate limiting.** `enforce_rate_limit` keys every policy on + `sha256(CF-Connecting-IP)` (`backend/src/services/request_rate_limit.py:36`). + Login allows 10 requests / 15 min and registration 5 / hour. Twenty students + behind one campus NAT share one key, so users 11–20 get `429`. This needs no + load test — it is arithmetic — but it also constrains how the harness works + (see *pre-minted sessions* below). +2. **Pyodide cold start under isolate fan-out.** Concurrent arrivals spread + across fresh isolates, and Pyodide init has crashed there before. This is the + primary thing the run is looking for, and it only reproduces through the + Pages origin. +3. **Sequential D1 round-trips.** `/api/me/progress` issues ~7 sequential + queries, the catalog service ~19. Expect p95 to degrade before anything + errors. + +Four design decisions follow from that: + +- **Load is generated over HTTP, not by driving 20 browsers.** The crash surface + is server-side isolate scheduling; the server cannot tell a browser from a + load generator. Twenty real browsers on one machine would be client-CPU-bound + and would measure the test runner instead. What browsers *would* catch — + whether the app still feels usable — is covered by keeping one real browser + open during the run as a canary. +- **The request sequence is recorded, not hand-written.** A hand-written list + tests an assumption about what the app does. `build-scenario.mjs` derives it + from `sessionStorage['studyplanner:api-request-log']`, which the app already + maintains (`frontend/src/shared/utils/apiRequestLog.ts`). +- **Sessions are pre-minted.** Logging in inside the test would hit the 10/15min + limit at VU 11 and measure the limiter. `mint-sessions.mjs` collects cookies + out of band; they last 30 days. +- **The target is the Pages origin** (`https://studyplaner.pages.dev`), not + `studyplanner-api.*.workers.dev`. The Worker origin bypasses the Pages + Function and its service binding (`frontend/functions/_shared/proxy.ts`) and + structurally cannot reproduce risk 2. + +Note that unauthenticated `GET /api/catalog/*` is served from `caches.default` +(`proxy.ts:65`). An anonymous test would measure a CDN cache, which is why every +step runs authenticated. + +## Prerequisites + +k6 as a standalone binary — it is not an npm dependency of this repo: + +```bash +winget install k6 --source winget +``` + +Node 18+ for the two `.mjs` helpers (no packages needed; they use built-in +`fetch`). + +Pick a throwaway password and export it once per shell. It is never stored in +the repo: + +```bash +export LOADTEST_PASSWORD='' +``` + +## One-time setup + +### 1. Seed the accounts + +```bash +py backend/scripts/seed_load_test_users.py --count 20 --apply +``` + +Writes `loadtest-01@example.com` … `loadtest-20@example.com` to the production +D1. Dry-run without `--apply`. Re-running is safe — credentials are upserted and +existing planner data is left alone. + +These accounts are retained after a run, like the `debug-onboarding-*` accounts +in `CLAUDE.md`. Exclude them from user counts. + +### 2. Record a real session + +The committed `recorded-session.json` starts as a **placeholder** derived from +reading `frontend/src`. Replace it with a real recording before trusting any +results; `scenario.js` warns until you do. + +1. Open `https://studyplaner.pages.dev` and log in as `loadtest-01@example.com`. +2. Walk a representative session: browse the catalog, open the planner, add a + course, look at progress. +3. In DevTools console, dump the log the app already kept: + + ```js + copy(sessionStorage.getItem('studyplanner:api-request-log')) + ``` + +4. Save the clipboard to a file and convert it: + + ```bash + node load-test/build-scenario.mjs raw-dump.json + ``` + +The converter drops endpoints that must not be replayed (login, register, +logout, feedback, client-errors) and prints why for each. + +Re-record whenever the frontend's data fetching changes. + +### 3. Mint sessions + +```bash +node load-test/mint-sessions.mjs --count 20 +``` + +Takes ~15 minutes: it logs in 9 accounts, waits for the next fixed 15-minute +rate-limit window, then does the rest. Output `sessions.json` holds live session +cookies — it is gitignored, treat it as a credential file. Valid 30 days, so one +mint covers many runs. + +## Running + +Smoke check first. It must pass before any multi-VU run: + +```bash +k6 run --vus 1 --iterations 1 load-test/scenario.js +``` + +Then the real run — 20 VUs, ramp over 30s, hold 5 minutes: + +```bash +k6 run load-test/scenario.js +``` + +While it runs, in two other terminals: + +```bash +npx wrangler tail studyplanner-api --format pretty +``` + +…and keep one real browser open on the app as a usability canary. A 500 in k6 +tells you *that* it broke; the tail tells you whether Pyodide init was the +cause. + +Phase D, separately, at least 15 minutes after minting: + +```bash +k6 run -e LOADTEST_PASSWORD="$LOADTEST_PASSWORD" load-test/login-burst.js +``` + +## Reading the result + +The run **fails** if either gate trips: + +| Gate | Meaning | +| --- | --- | +| `server_errors > 0` | 5xx observed — the finding. Correlate with `wrangler tail`. | +| `rate_limited_429 > 0` | The limiter was hit, so the run measured the limiter. Results are invalid; re-mint sessions and re-run. | +| `http_req_failed > 1%` | Non-5xx failures — timeouts, connection resets. | +| `http_req_duration p95 > 1500ms` | Latency budget exceeded. | + +Full per-endpoint data lands in `load-test/results/summary.json`. Quote raw +numbers from it in the report rather than summarising twice. + +## Safety + +- The run writes to the **production** D1. Writes are confined to the + `loadtest-*` accounts' own semester plans. +- `POST /api/feedback` and `/api/client-errors` are excluded by + `build-scenario.mjs` — both are hourly-limited per IP and would pollute the + diagnostics view. +- Run at a low-traffic hour; a 20-VU burst can briefly affect real users. diff --git a/load-test/build-scenario.mjs b/load-test/build-scenario.mjs new file mode 100644 index 0000000..34088d7 --- /dev/null +++ b/load-test/build-scenario.mjs @@ -0,0 +1,113 @@ +/** + * Turns a real browser session into the request sequence k6 replays. + * + * node load-test/build-scenario.mjs + * + * Input is a dump of `sessionStorage['studyplanner:api-request-log']`, which the + * app already maintains for its own diagnostics + * (frontend/src/shared/utils/apiRequestLog.ts). Entries are stored newest-first + * and capped at 80, so this reverses them into chronological order. + * + * The point of generating the scenario rather than hand-writing it: a + * hand-written request list tests an assumption about what the app does. A + * recording is what it actually did. See load-test/README.md for how to capture + * the dump. + * + * Output: load-test/recorded-session.json — committed, so a run is reproducible + * and the recording can be refreshed when the frontend changes. + */ + +import { readFileSync, writeFileSync } from 'node:fs' +import { fileURLToPath } from 'node:url' +import { dirname, join } from 'node:path' + +const SCRIPT_DIR = dirname(fileURLToPath(import.meta.url)) +const OUTPUT_PATH = join(SCRIPT_DIR, 'recorded-session.json') + +/** + * Endpoints that must never be replayed under load, with the reason. + * Keep in sync with the policies in backend/src/services/request_rate_limit.py. + */ +const EXCLUDED_PATHS = new Map([ + ['/api/auth/login', 'rate limited to 10/15min per IP; sessions are pre-minted instead'], + ['/api/auth/register', 'rate limited to 5/hour per IP'], + ['/api/auth/logout', 'would invalidate the pre-minted session mid-run'], + ['/api/feedback', 'rate limited to 5/hour per IP and writes user-visible feedback rows'], + ['/api/client-errors', 'rate limited to 30/hour per IP and pollutes the diagnostics view'], +]) + +function toPath(rawUrl) { + try { + return new URL(rawUrl).pathname + new URL(rawUrl).search + } catch { + // The log stores same-origin relative URLs when VITE_API_BASE_URL is unset. + return rawUrl + } +} + +function buildSteps(entries) { + const chronological = [...entries].sort((left, right) => left.timestamp - right.timestamp) + const steps = [] + const skipped = [] + + for (const entry of chronological) { + const path = toPath(entry.url) + const pathWithoutQuery = path.split('?')[0] + + if (!pathWithoutQuery.startsWith('/api/')) { + continue + } + const exclusionReason = EXCLUDED_PATHS.get(pathWithoutQuery) + if (exclusionReason) { + skipped.push({ path: pathWithoutQuery, reason: exclusionReason }) + continue + } + + steps.push({ + method: (entry.method ?? 'GET').toUpperCase(), + path, + observedStatus: entry.status, + observedDurationMs: entry.durationMs ?? null, + }) + } + + return { steps, skipped } +} + +function main() { + const inputPath = process.argv[2] + if (!inputPath) { + throw new Error('Usage: node load-test/build-scenario.mjs ') + } + + const parsed = JSON.parse(readFileSync(inputPath, 'utf8')) + const entries = Array.isArray(parsed) ? parsed : parsed.entries + if (!Array.isArray(entries)) { + throw new Error('Input must be the sessionStorage array, or an object with an `entries` array.') + } + + const { steps, skipped } = buildSteps(entries) + if (steps.length === 0) { + throw new Error('No /api/ requests found in the dump — was the log captured after a page reload?') + } + + const recording = { + source: 'recorded', + recordedAt: new Date().toISOString(), + stepCount: steps.length, + steps, + } + + writeFileSync(OUTPUT_PATH, `${JSON.stringify(recording, null, 2)}\n`, 'utf8') + console.log(`[build-scenario] wrote ${OUTPUT_PATH} (${steps.length} steps)`) + for (const { path, reason } of skipped) { + console.log(`[build-scenario] excluded ${path} — ${reason}`) + } +} + +try { + main() +} catch (error) { + console.error(`[build-scenario] ${error.message}`) + process.exitCode = 1 +} diff --git a/load-test/login-burst.js b/load-test/login-burst.js new file mode 100644 index 0000000..757fcd8 --- /dev/null +++ b/load-test/login-burst.js @@ -0,0 +1,71 @@ +/** + * Phase D: how does login behave when several people sign in at once? + * + * k6 run load-test/login-burst.js + * + * Login is the most CPU-expensive request in the app: _hash_password() runs + * PBKDF2-HMAC-SHA256 at 310,000 iterations + * (backend/src/services/authentication.py) inside Pyodide, on top of a D1 write + * from the rate limiter itself. + * + * Deliberately 8 VUs, one iteration each: AUTH_LOGIN_POLICY allows 10 logins + * per 15-minute window per IP, so 8 measures login cost with headroom instead + * of measuring the limiter. Raising this above 9 will produce 429s. + * + * Consumes login budget for the whole IP — do not run this within 15 minutes of + * mint-sessions.mjs. + */ + +import http from 'k6/http' +import { check } from 'k6' +import { Counter } from 'k6/metrics' + +const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' +const ORIGIN = (__ENV.LOADTEST_ORIGIN || DEFAULT_ORIGIN).replace(/\/$/, '') +const PASSWORD = __ENV.LOADTEST_PASSWORD + +const BURST_SIZE = 8 + +const rateLimited = new Counter('rate_limited_429') + +export const options = { + scenarios: { + login_burst: { + executor: 'per-vu-iterations', + vus: BURST_SIZE, + iterations: 1, + maxDuration: '2m', + }, + }, + thresholds: { + rate_limited_429: ['count<1'], + http_req_failed: ['rate<0.01'], + }, +} + +export function setup() { + if (!PASSWORD) { + throw new Error('Run with -e LOADTEST_PASSWORD=') + } + console.log(`[login-burst] ${BURST_SIZE} simultaneous logins against ${ORIGIN}`) +} + +export default function login() { + const username = `loadtest-${String(__VU).padStart(2, '0')}@example.com` + const response = http.post( + `${ORIGIN}/api/auth/login`, + JSON.stringify({ identifier: username, password: PASSWORD }), + { headers: { 'Content-Type': 'application/json' }, tags: { endpoint: '/api/auth/login' } }, + ) + + if (response.status === 429) { + rateLimited.add(1) + } + + check(response, { + 'login succeeded': (r) => r.status === 200, + 'not rate limited': (r) => r.status !== 429, + }) + + console.log(`[login-burst] vu=${__VU} status=${response.status} duration=${response.timings.duration.toFixed(0)}ms`) +} diff --git a/load-test/mint-sessions.mjs b/load-test/mint-sessions.mjs new file mode 100644 index 0000000..a91ee14 --- /dev/null +++ b/load-test/mint-sessions.mjs @@ -0,0 +1,152 @@ +/** + * Logs the seeded loadtest-* accounts in and saves their session cookies for k6. + * + * node load-test/mint-sessions.mjs --count 20 + * + * Run this well before the load run, not as part of it. AUTH_LOGIN_POLICY + * (backend/src/services/request_rate_limit.py) allows 10 logins per 15-minute + * window per client IP, so minting 20 sessions from one machine spans two + * windows. Doing it inside the load test would mean measuring the rate limiter + * instead of the app. + * + * The rate limiter uses a fixed window aligned to wall-clock time + * (`now - (now % window_seconds)`), so this waits for the next 900s boundary + * rather than sleeping a blind 15 minutes. + * + * Sessions stay valid for AUTH_TOKEN_TTL_SECONDS (30 days), so one mint covers + * many runs. + * + * Output: load-test/sessions.json — gitignored, it contains live session + * cookies. Treat it as a credential file. + */ + +import { writeFileSync } from 'node:fs' +import { fileURLToPath } from 'node:url' +import { dirname, join } from 'node:path' + +const SCRIPT_DIR = dirname(fileURLToPath(import.meta.url)) +const OUTPUT_PATH = join(SCRIPT_DIR, 'sessions.json') + +const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' +const DEFAULT_COUNT = 20 +const ACCOUNT_TEMPLATE = (index) => `loadtest-${String(index).padStart(2, '0')}@example.com` + +const AUTH_COOKIE_NAME = 'studyplanner_session' +const LOGIN_WINDOW_SECONDS = 15 * 60 +const LOGIN_LIMIT_PER_WINDOW = 10 +// One request of headroom, so an unrelated login from the same IP does not +// push the batch over the limit. +const LOGINS_PER_BATCH = LOGIN_LIMIT_PER_WINDOW - 1 + +function parseArguments(argv) { + const args = { origin: DEFAULT_ORIGIN, count: DEFAULT_COUNT } + for (let index = 0; index < argv.length; index += 1) { + const flag = argv[index] + if (flag === '--origin') { + args.origin = argv[index + 1] + index += 1 + } else if (flag === '--count') { + args.count = Number.parseInt(argv[index + 1], 10) + index += 1 + } + } + if (!Number.isInteger(args.count) || args.count < 1) { + throw new Error('--count must be a positive integer') + } + return args +} + +function extractSessionCookie(setCookieHeaders) { + for (const header of setCookieHeaders) { + const [pair] = header.split(';') + const separatorIndex = pair.indexOf('=') + if (pair.slice(0, separatorIndex).trim() === AUTH_COOKIE_NAME) { + return pair.slice(separatorIndex + 1).trim() + } + } + return null +} + +function secondsUntilNextWindow() { + const nowSeconds = Math.floor(Date.now() / 1000) + const nextBoundary = (Math.floor(nowSeconds / LOGIN_WINDOW_SECONDS) + 1) * LOGIN_WINDOW_SECONDS + // One extra second so the boundary has definitely passed server-side. + return nextBoundary - nowSeconds + 1 +} + +function sleep(seconds) { + return new Promise((resolve) => { + setTimeout(resolve, seconds * 1000) + }) +} + +async function login(origin, username, password) { + const response = await fetch(`${origin}/api/auth/login`, { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: JSON.stringify({ identifier: username, password }), + redirect: 'manual', + }) + + const bodyText = await response.text() + if (response.status === 429) { + throw new Error(`rate limited (429) for ${username}; retry after the next 15-minute window`) + } + if (!response.ok) { + throw new Error(`login failed for ${username}: ${response.status} ${bodyText.slice(0, 200)}`) + } + + const sessionCookie = extractSessionCookie(response.headers.getSetCookie()) + if (!sessionCookie) { + throw new Error(`login for ${username} returned no ${AUTH_COOKIE_NAME} cookie`) + } + + const payload = JSON.parse(bodyText) + if (!payload.csrfToken) { + throw new Error(`login for ${username} returned no csrfToken`) + } + + return { username, sessionCookie, csrfToken: payload.csrfToken } +} + +async function main() { + const args = parseArguments(process.argv.slice(2)) + const password = (process.env.LOADTEST_PASSWORD ?? '').trim() + if (!password) { + throw new Error( + 'LOADTEST_PASSWORD is not set. Use the same value passed to seed_load_test_users.py.', + ) + } + + const usernames = Array.from({ length: args.count }, (_, index) => ACCOUNT_TEMPLATE(index + 1)) + const sessions = [] + + console.log(`[mint] ${usernames.length} accounts against ${args.origin}`) + console.log(`[mint] batches of ${LOGINS_PER_BATCH} per ${LOGIN_WINDOW_SECONDS / 60}-minute window`) + + for (let index = 0; index < usernames.length; index += 1) { + if (index > 0 && index % LOGINS_PER_BATCH === 0) { + const waitSeconds = secondsUntilNextWindow() + console.log(`[mint] login window full — waiting ${waitSeconds}s for the next window ...`) + await sleep(waitSeconds) + } + + const username = usernames[index] + const session = await login(args.origin, username, password) + sessions.push(session) + console.log(`[mint] ${index + 1}/${usernames.length} ${username}`) + } + + writeFileSync( + OUTPUT_PATH, + `${JSON.stringify({ origin: args.origin, mintedAt: new Date().toISOString(), sessions }, null, 2)}\n`, + 'utf8', + ) + console.log(`[mint] wrote ${OUTPUT_PATH} (${sessions.length} sessions)`) + console.log('[mint] this file contains live session cookies — it is gitignored, do not share it') +} + +main().catch((error) => { + console.error(`[mint] ${error.message}`) + process.exitCode = 1 +}) diff --git a/load-test/recorded-session.json b/load-test/recorded-session.json new file mode 100644 index 0000000..c41461f --- /dev/null +++ b/load-test/recorded-session.json @@ -0,0 +1,19 @@ +{ + "source": "placeholder", + "note": "Derived from endpoint usage in frontend/src, NOT from a real browser session. Replace it with a real recording before trusting any results: see load-test/README.md, then run `node load-test/build-scenario.mjs `. scenario.js warns while this stays a placeholder.", + "recordedAt": null, + "stepCount": 11, + "steps": [ + { "method": "GET", "path": "/api/auth/session", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/config", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/profile", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/catalog/periods", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/catalog/courses?limit=100&period=all", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/study-programs", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/favorites", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/completed-courses", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/semester-plans", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/progress", "observedStatus": 200, "observedDurationMs": null }, + { "method": "PUT", "path": "/api/me/semester-plans/WiSe%202026%2F27", "observedStatus": 200, "observedDurationMs": null } + ] +} diff --git a/load-test/scenario.js b/load-test/scenario.js new file mode 100644 index 0000000..370bb71 --- /dev/null +++ b/load-test/scenario.js @@ -0,0 +1,215 @@ +/** + * Replays a recorded StudyPlanner session at ~20 concurrent users. + * + * k6 run load-test/scenario.js # 20 VUs, 5 minutes + * k6 run --vus 1 --iterations 1 load-test/scenario.js # smoke check first + * + * Requires: + * - load-test/sessions.json (node load-test/mint-sessions.mjs) + * - load-test/recorded-session.json (node load-test/build-scenario.mjs) + * + * Targets the Pages origin, not the Worker origin. Requests must pass through + * the Pages Function and its service binding + * (frontend/functions/_shared/proxy.ts) — that is the path where the Pyodide + * cold-start 500s appear. Hitting studyplanner-api.*.workers.dev directly + * bypasses it and cannot reproduce them. + */ + +import http from 'k6/http' +import { check, sleep } from 'k6' +import { Counter, Trend } from 'k6/metrics' +import { scenario } from 'k6/execution' + +const AUTH_COOKIE_NAME = 'studyplanner_session' +const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' + +// Think time between steps. A hot loop is not a user simulation: it changes +// both the arrival pattern and how many isolates the requests fan across, +// which is the thing under test. +const MIN_THINK_SECONDS = 3 +const MAX_THINK_SECONDS = 8 + +const sessionsFile = JSON.parse(open('./sessions.json')) +const recording = JSON.parse(open('./recorded-session.json')) + +const ORIGIN = (__ENV.LOADTEST_ORIGIN || sessionsFile.origin || DEFAULT_ORIGIN).replace(/\/$/, '') + +// The finding we care about is 5xx, and an average hides a handful of them. +const serverErrors = new Counter('server_errors') +const rateLimited = new Counter('rate_limited_429') +const stepDuration = new Trend('step_duration', true) + +export const options = { + scenarios: { + concurrent_users: { + executor: 'ramping-vus', + startVUs: 0, + stages: [ + { duration: '30s', target: 20 }, + { duration: '5m', target: 20 }, + { duration: '10s', target: 0 }, + ], + gracefulRampDown: '30s', + }, + }, + thresholds: { + // Any 5xx fails the run outright. + server_errors: ['count<1'], + // A 429 here means the pre-minted sessions were not enough to keep the + // rate limiter out of the measurement — the run is invalid, not the app. + rate_limited_429: ['count<1'], + http_req_failed: ['rate<0.01'], + http_req_duration: ['p(95)<1500'], + }, +} + +export function setup() { + if (recording.source === 'placeholder') { + console.warn( + '[scenario] recorded-session.json is still the PLACEHOLDER derived from source code, ' + + 'not a real browser recording. Results describe an assumed request sequence. ' + + 'See load-test/README.md.', + ) + } + console.log(`[scenario] origin=${ORIGIN} steps=${recording.steps.length} sessions=${sessionsFile.sessions.length}`) + return { stepCount: recording.steps.length } +} + +function thinkTime() { + return MIN_THINK_SECONDS + Math.random() * (MAX_THINK_SECONDS - MIN_THINK_SECONDS) +} + +function pickSession() { + // Stable VU-to-account mapping, so one account's rows are not written + // concurrently by several VUs. + const sessions = sessionsFile.sessions + return sessions[(__VU - 1) % sessions.length] +} + +function buildHeaders(session, method) { + const headers = { + Cookie: `${AUTH_COOKIE_NAME}=${session.sessionCookie}`, + Accept: 'application/json', + } + if (method !== 'GET' && method !== 'HEAD') { + // require_csrf_protection() rejects mutations on /api/me/* without this. + headers['X-CSRF-Token'] = session.csrfToken + headers['Content-Type'] = 'application/json' + } + return headers +} + +/** + * Body for the one write in the scenario. Course ids come from the catalog + * response earlier in the same iteration so the write stores plausible data; + * an empty plan is still valid if the catalog step returned nothing usable. + */ +function buildWriteBody(courseIds) { + return JSON.stringify({ + courseIds: courseIds.slice(0, 5), + hiddenSlotIds: [], + courseAssignments: {}, + }) +} + +function collectCourseIds(response) { + try { + const payload = response.json() + const courses = payload && payload.courses + if (!Array.isArray(courses)) { + return [] + } + return courses.map((course) => course.id).filter((id) => Number.isInteger(id)) + } catch { + return [] + } +} + +export default function runUserSession() { + const session = pickSession() + let courseIds = [] + + for (const step of recording.steps) { + const pathWithoutQuery = step.path.split('?')[0] + const isWrite = step.method !== 'GET' && step.method !== 'HEAD' + const body = isWrite ? buildWriteBody(courseIds) : null + + const response = http.request(step.method, `${ORIGIN}${step.path}`, body, { + headers: buildHeaders(session, step.method), + // Group metrics by endpoint rather than by unique URL. + tags: { endpoint: pathWithoutQuery, method: step.method }, + redirects: 0, + }) + + stepDuration.add(response.timings.duration, { endpoint: pathWithoutQuery }) + + if (response.status >= 500) { + serverErrors.add(1, { endpoint: pathWithoutQuery }) + console.error( + `[scenario] ${response.status} ${step.method} ${pathWithoutQuery} ` + + `vu=${__VU} iter=${scenario.iterationInTest} body=${String(response.body).slice(0, 200)}`, + ) + } + if (response.status === 429) { + rateLimited.add(1, { endpoint: pathWithoutQuery }) + } + + check(response, { + 'status is not 5xx': (r) => r.status < 500, + 'status is not 429': (r) => r.status !== 429, + 'status is 2xx': (r) => r.status >= 200 && r.status < 300, + }, { endpoint: pathWithoutQuery }) + + if (pathWithoutQuery === '/api/catalog/courses' && response.status === 200) { + courseIds = collectCourseIds(response) + } + + sleep(thinkTime()) + } +} + +function counterValue(data, metricName) { + const metric = data.metrics[metricName] + return metric ? metric.values.count : 0 +} + +function formatLatency(data, metricName) { + const metric = data.metrics[metricName] + if (!metric || metric.values.p95 === undefined) { + return `${metricName}: n/a` + } + const { med, 'p(95)': p95, 'p(99)': p99, max } = metric.values + return `${metricName}: med=${med.toFixed(0)}ms p95=${p95.toFixed(0)}ms p99=${(p99 ?? 0).toFixed(0)}ms max=${max.toFixed(0)}ms` +} + +/** + * Overriding handleSummary replaces k6's built-in table, so this reprints the + * numbers the report needs. The full dataset (including per-endpoint tags) goes + * to JSON so docs/load-test-*.md can quote raw figures rather than a summary of + * a summary. + */ +export function handleSummary(data) { + const serverErrorCount = counterValue(data, 'server_errors') + const rateLimitedCount = counterValue(data, 'rate_limited_429') + const failedRate = data.metrics.http_req_failed + ? (data.metrics.http_req_failed.values.rate * 100).toFixed(2) + : 'n/a' + + const lines = [ + '', + '=== StudyPlanner concurrent-user run ===', + `requests: ${counterValue(data, 'http_reqs')}`, + `failed: ${failedRate}%`, + `server_errors: ${serverErrorCount}${serverErrorCount > 0 ? ' <-- FAIL: 5xx observed' : ''}`, + `rate_limited: ${rateLimitedCount}${rateLimitedCount > 0 ? ' <-- run invalid: limiter was hit' : ''}`, + formatLatency(data, 'http_req_duration'), + formatLatency(data, 'step_duration'), + 'full per-endpoint data: load-test/results/summary.json', + '', + ] + + return { + stdout: lines.join('\n'), + 'load-test/results/summary.json': JSON.stringify(data, null, 2), + } +} From be5c55f46f524725d4b46472c48627c02ffe9b85 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 10:46:05 +0200 Subject: [PATCH 2/8] Correct load-test target origin and caching model from live observation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase 0 reconnaissance against production contradicted three assumptions the harness was built on. Findings and measurements are in docs/load-test-2026-08.md. The deployed frontend calls the Worker origin directly. VITE_API_BASE_URL is baked into the Pages build, so browsers never touch the same-origin /api/* Pages Function — the previous commit targeted the wrong host. Points scenario.js, mint-sessions.mjs and login-burst.js at studyplanner-api.*.workers.dev. A side effect worth recording: the caches.default catalog cache in functions/_shared/proxy.ts is therefore never exercised by web users. It still responds correctly when called directly, so this is dead weight rather than breakage. The catalog is fetched once per browser session, not per page view: responses carry s-maxage=900 and the frontend caches them in sessionStorage for 24h (shared/utils/sessionCache.ts, observed as a 1.43 MB entry). Replaying the full sequence every iteration would have invented backend load that does not exist, so build-scenario.mjs now splits a recording into firstLoad and steadyState and scenario.js runs firstLoad on __ITER === 0 only. That also matches the scenario under test more closely: twenty people opening the app at the start of a lecture is a burst of expensive session starts, not sustained traffic. Single-user latency, measured with no contention, dwarfs anything concurrency is likely to add: the 1.43 MB catalog took 12.7s cold and 3.3s warm, and /api/config takes 2.7s warm to return a single null field. Small sample, recorded as an order of magnitude for Phase B to replace with real percentiles. recorded-session.json now carries the real anonymous first-load steps and their observed timings; the authenticated steps remain assumed until a logged-in session can be recorded. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 81 +++++++++++++++++++++++++---- load-test/README.md | 21 +++++--- load-test/build-scenario.mjs | 90 +++++++++++++++++++++++++++++---- load-test/login-burst.js | 2 +- load-test/mint-sessions.mjs | 2 +- load-test/recorded-session.json | 20 ++++---- load-test/scenario.js | 53 +++++++++++++------ 7 files changed, 216 insertions(+), 53 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 366ccb1..63a06b1 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -5,7 +5,8 @@ its design live in [`load-test/README.md`](../load-test/README.md). | | | | --- | --- | -| Target | `https://studyplaner.pages.dev` (production Pages origin) | +| Target | `https://studyplanner-api.ben-tischberger.workers.dev` (see Phase 0) | +| Frontend | Pages `studyplaner.pages.dev` | | Backend | Worker `studyplanner-api`, D1 `studyplanner-db` | | Harness | k6 (standalone binary, not an npm dependency) | | Accounts | `loadtest-01@example.com` … `loadtest-20@example.com` | @@ -14,14 +15,75 @@ its design live in [`load-test/README.md`](../load-test/README.md). | Phase | What it establishes | Status | | --- | --- | --- | -| A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | **Confirmed by code reading; live check pending** | -| B — baseline | Uncontended per-endpoint latency | Not run | +| 0 — live reconnaissance | Which origin users actually hit; single-user latency | **Done (2026-08-07, anonymous)** | +| A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | Confirmed by code reading; live check pending | +| B — baseline | Uncontended per-endpoint latency, authenticated | Not run | | C — 20 concurrent users | 5xx under isolate fan-out; p95 under load | Not run | | D — login burst | How CPU-bound logins queue | Not run | Phases B–D need the one-time setup in the harness README (seed accounts, record -a session, mint sessions). Until then `load-test/recorded-session.json` is a -placeholder derived from `frontend/src`, not a real recording. +an authenticated session, mint sessions). + +--- + +## Phase 0 — live reconnaissance + +Measured against production on 2026-08-07 from a browser, anonymous, one user. +Timings come from the app's own request log +(`sessionStorage['studyplanner:api-request-log']`). + +### The frontend does not use the Pages API proxy + +Every API call from the deployed app goes to +`https://studyplanner-api.ben-tischberger.workers.dev` directly. The origin is +baked into the Pages build (`VITE_API_BASE_URL`, resolved by +[`apiBaseUrl.ts`](../frontend/src/shared/utils/apiBaseUrl.ts)) and appears in the +shipped bundle chunk. + +Two consequences: + +- **The load test must target the Worker origin**, not the Pages origin. An + earlier draft of this plan had it backwards. +- **`functions/api/[[path]].ts` and its `caches.default` catalog caching are not + in the production user path.** The `isPublicCatalogRequest` cache in + [`proxy.ts:65`](../frontend/functions/_shared/proxy.ts) never runs for web + users. The same-origin path still responds correctly if called directly, so + this is dead weight rather than breakage — but it means an optimisation + believed to be active is not. + +### Single-user latency is the headline problem + +| Request | Cold | Warm (browser cache bypassed) | Browser-cached | +| --- | --- | --- | --- | +| `GET /api/catalog/courses?limit=1000&period=all` (1.43 MB) | 12,693 ms | 3,280 ms | 26 ms | +| `GET /api/catalog/periods` | 1,582 ms | — | 23 ms | +| `GET /api/config` | 5,699 ms | 2,698 ms | — | +| `GET /api/auth/session` | 1,943 ms | 1,080 ms | — | + +These are seconds, at **one** user with no contention. `/api/config` returns +`{"simulatedSemesterLabel": null}` and still took 2.7 s warm. Concurrency is not +the first problem here; baseline per-request cost is. + +Sample sizes are small (1–2 observations per cell) — treat them as an order of +magnitude, not a measurement. Phase B replaces them with real percentiles. + +### The catalog is cached, twice + +Public catalog responses carry +`Cache-Control: public, max-age=300, s-maxage=900, stale-while-revalidate=86400`, +and the frontend additionally stores them in `sessionStorage` for 24 h +([`sessionCache.ts`](../frontend/src/shared/utils/sessionCache.ts)) — the +observed 1.43 MB entry. + +So a real user fetches the 1.43 MB catalog **once per browser session**, not per +page view. A load scenario that re-requests it every iteration would invent +backend load that does not exist. `build-scenario.mjs` therefore splits the +recording into a first-load phase (run once per VU) and a steady state. + +That split also reframes the test: twenty people opening the app at the start of +a lecture is a burst of twenty expensive session starts, not sustained traffic. +Whether the second through twentieth of those hit an edge cache or all pay the +~3.3 s origin cost is exactly what Phase C should answer. --- @@ -85,12 +147,11 @@ Expected pressure points, from reading the code: - `/api/me/progress` issues ~7 sequential D1 queries ([`progress.py`](../backend/src/services/progress.py)); the catalog service ~19. Latency is additive per request and D1 has one primary region. -- Authenticated requests bypass the Pages `caches.default` layer that serves - anonymous `GET /api/catalog/*` - ([`proxy.ts:65`](../frontend/functions/_shared/proxy.ts)), so every step here - reaches the Worker. +- Authenticated endpoints carry no `Cache-Control`, so unlike the public catalog + they reach the Worker on every request. - Pyodide init on cold isolates is the suspected source of the previously - observed production 500s. + observed production 500s, and Phase 0 measured a 12.7 s cold catalog request + against 3.3 s warm — consistent with an expensive init on the cold path. ## Phase D — login burst diff --git a/load-test/README.md b/load-test/README.md index 7683711..4a2a131 100644 --- a/load-test/README.md +++ b/load-test/README.md @@ -36,14 +36,19 @@ Four design decisions follow from that: - **Sessions are pre-minted.** Logging in inside the test would hit the 10/15min limit at VU 11 and measure the limiter. `mint-sessions.mjs` collects cookies out of band; they last 30 days. -- **The target is the Pages origin** (`https://studyplaner.pages.dev`), not - `studyplanner-api.*.workers.dev`. The Worker origin bypasses the Pages - Function and its service binding (`frontend/functions/_shared/proxy.ts`) and - structurally cannot reproduce risk 2. - -Note that unauthenticated `GET /api/catalog/*` is served from `caches.default` -(`proxy.ts:65`). An anonymous test would measure a CDN cache, which is why every -step runs authenticated. +- **The target is the Worker origin** + (`https://studyplanner-api.ben-tischberger.workers.dev`), because that is what + the deployed frontend calls. `VITE_API_BASE_URL` is baked into the Pages + build, so browsers skip the same-origin `/api/*` Pages Function entirely. + Verified against the live bundle — see `docs/load-test-2026-08.md` Phase 0. + (The `caches.default` catalog cache in `proxy.ts:65` consequently never runs + for web users.) +- **Each VU does one expensive first load, then a lighter steady state.** The + frontend caches the catalog, progress and planner payloads in `sessionStorage` + for 24 h (`frontend/src/shared/utils/sessionCache.ts`), so a real user fetches + the 1.43 MB catalog once per browser session. Replaying it every iteration + would invent load that does not exist. `scenario.js` runs the first-load steps + on `__ITER === 0` only. ## Prerequisites diff --git a/load-test/build-scenario.mjs b/load-test/build-scenario.mjs index 34088d7..dca092b 100644 --- a/load-test/build-scenario.mjs +++ b/load-test/build-scenario.mjs @@ -24,6 +24,41 @@ import { dirname, join } from 'node:path' const SCRIPT_DIR = dirname(fileURLToPath(import.meta.url)) const OUTPUT_PATH = join(SCRIPT_DIR, 'recorded-session.json') +// The deployed frontend calls the Worker directly (VITE_API_BASE_URL is baked +// into the Pages build), so this is the origin real users hit — not the +// same-origin /api/* path served by the Pages Function. +const DEFAULT_API_ORIGIN = 'https://studyplanner-api.ben-tischberger.workers.dev' + +/** + * Endpoints the frontend caches in sessionStorage for 24h + * (frontend/src/shared/utils/sessionCache.ts). A real user hits these once when + * the browser session starts and then reads from cache, so replaying them every + * iteration would invent backend load that does not exist. + * + * They are split into a first-load phase that each VU runs once. That also + * happens to be the realistic shape of the scenario under test: twenty people + * opening the app at the start of a lecture is a burst of expensive session + * starts, not sustained traffic. + */ +/** Fetched once when the app boots, not on every view change. */ +const BOOTSTRAP_PATHS = new Set([ + '/api/config', + '/api/auth/session', + '/api/me/profile', + '/api/study-programs', + '/api/me/favorites', +]) + +const SESSION_CACHED_PATHS = new Set([ + '/api/catalog/courses', + '/api/catalog/periods', + '/api/me/progress', + '/api/me/semester-plans', + '/api/me/completed-courses', + '/api/me/transcript-data', + '/api/me/transcript-issues', +]) + /** * Endpoints that must never be replayed under load, with the reason. * Keep in sync with the policies in backend/src/services/request_rate_limit.py. @@ -45,10 +80,20 @@ function toPath(rawUrl) { } } +function isSessionCached(pathWithoutQuery) { + if (SESSION_CACHED_PATHS.has(pathWithoutQuery)) { + return true + } + // Course detail is cached per course id. + return pathWithoutQuery.startsWith('/api/catalog/courses/') +} + function buildSteps(entries) { const chronological = [...entries].sort((left, right) => left.timestamp - right.timestamp) - const steps = [] + const firstLoad = [] + const steadyState = [] const skipped = [] + const seenCachedPaths = new Set() for (const entry of chronological) { const path = toPath(entry.url) @@ -63,15 +108,32 @@ function buildSteps(entries) { continue } - steps.push({ + const step = { method: (entry.method ?? 'GET').toUpperCase(), path, observedStatus: entry.status, observedDurationMs: entry.durationMs ?? null, - }) + } + + const isRead = step.method === 'GET' + const runsOncePerSession = isRead + && (BOOTSTRAP_PATHS.has(pathWithoutQuery) || isSessionCached(pathWithoutQuery)) + + if (runsOncePerSession) { + // Only the first occurrence reaches the network in a real session; later + // ones come from sessionStorage or are simply not re-requested. + if (!seenCachedPaths.has(path)) { + seenCachedPaths.add(path) + firstLoad.push(step) + } + continue + } + + // Uncached reads and every write happen throughout the session. + steadyState.push(step) } - return { steps, skipped } + return { firstLoad, steadyState, skipped } } function main() { @@ -86,23 +148,33 @@ function main() { throw new Error('Input must be the sessionStorage array, or an object with an `entries` array.') } - const { steps, skipped } = buildSteps(entries) - if (steps.length === 0) { + const { firstLoad, steadyState, skipped } = buildSteps(entries) + if (firstLoad.length === 0 && steadyState.length === 0) { throw new Error('No /api/ requests found in the dump — was the log captured after a page reload?') } const recording = { source: 'recorded', recordedAt: new Date().toISOString(), - stepCount: steps.length, - steps, + apiOrigin: DEFAULT_API_ORIGIN, + firstLoad, + steadyState, } writeFileSync(OUTPUT_PATH, `${JSON.stringify(recording, null, 2)}\n`, 'utf8') - console.log(`[build-scenario] wrote ${OUTPUT_PATH} (${steps.length} steps)`) + console.log( + `[build-scenario] wrote ${OUTPUT_PATH} ` + + `(${firstLoad.length} first-load steps, ${steadyState.length} steady-state steps)`, + ) for (const { path, reason } of skipped) { console.log(`[build-scenario] excluded ${path} — ${reason}`) } + if (steadyState.length === 0) { + console.warn( + '[build-scenario] no steady-state steps: the recording only covers a session start. ' + + 'Walk further through the app (open courses, edit a plan) and re-record.', + ) + } } try { diff --git a/load-test/login-burst.js b/load-test/login-burst.js index 757fcd8..d8e8571 100644 --- a/load-test/login-burst.js +++ b/load-test/login-burst.js @@ -20,7 +20,7 @@ import http from 'k6/http' import { check } from 'k6' import { Counter } from 'k6/metrics' -const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' +const DEFAULT_ORIGIN = 'https://studyplanner-api.ben-tischberger.workers.dev' const ORIGIN = (__ENV.LOADTEST_ORIGIN || DEFAULT_ORIGIN).replace(/\/$/, '') const PASSWORD = __ENV.LOADTEST_PASSWORD diff --git a/load-test/mint-sessions.mjs b/load-test/mint-sessions.mjs index a91ee14..fd0ac16 100644 --- a/load-test/mint-sessions.mjs +++ b/load-test/mint-sessions.mjs @@ -27,7 +27,7 @@ import { dirname, join } from 'node:path' const SCRIPT_DIR = dirname(fileURLToPath(import.meta.url)) const OUTPUT_PATH = join(SCRIPT_DIR, 'sessions.json') -const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' +const DEFAULT_ORIGIN = 'https://studyplanner-api.ben-tischberger.workers.dev' const DEFAULT_COUNT = 20 const ACCOUNT_TEMPLATE = (index) => `loadtest-${String(index).padStart(2, '0')}@example.com` diff --git a/load-test/recorded-session.json b/load-test/recorded-session.json index c41461f..831f47d 100644 --- a/load-test/recorded-session.json +++ b/load-test/recorded-session.json @@ -1,19 +1,21 @@ { "source": "placeholder", - "note": "Derived from endpoint usage in frontend/src, NOT from a real browser session. Replace it with a real recording before trusting any results: see load-test/README.md, then run `node load-test/build-scenario.mjs `. scenario.js warns while this stays a placeholder.", - "recordedAt": null, - "stepCount": 11, - "steps": [ - { "method": "GET", "path": "/api/auth/session", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/config", "observedStatus": 200, "observedDurationMs": null }, + "note": "Partly real: the firstLoad GETs and their durations were observed on https://studyplaner.pages.dev on 2026-08-07 as an ANONYMOUS visitor. The authenticated steps and all of steadyState are still assumed, derived from frontend/src. Replace by walking the app logged in and running `node load-test/build-scenario.mjs `. scenario.js warns while this stays a placeholder.", + "recordedAt": "2026-08-07T08:30:00.000Z", + "apiOrigin": "https://studyplanner-api.ben-tischberger.workers.dev", + "firstLoad": [ + { "method": "GET", "path": "/api/config", "observedStatus": 200, "observedDurationMs": 3516 }, + { "method": "GET", "path": "/api/auth/session", "observedStatus": 200, "observedDurationMs": 1758 }, + { "method": "GET", "path": "/api/catalog/periods", "observedStatus": 200, "observedDurationMs": 1582 }, + { "method": "GET", "path": "/api/catalog/courses?limit=1000&period=all", "observedStatus": 200, "observedDurationMs": 12693 }, { "method": "GET", "path": "/api/me/profile", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/catalog/periods", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/catalog/courses?limit=100&period=all", "observedStatus": 200, "observedDurationMs": null }, { "method": "GET", "path": "/api/study-programs", "observedStatus": 200, "observedDurationMs": null }, { "method": "GET", "path": "/api/me/favorites", "observedStatus": 200, "observedDurationMs": null }, { "method": "GET", "path": "/api/me/completed-courses", "observedStatus": 200, "observedDurationMs": null }, { "method": "GET", "path": "/api/me/semester-plans", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/me/progress", "observedStatus": 200, "observedDurationMs": null }, + { "method": "GET", "path": "/api/me/progress", "observedStatus": 200, "observedDurationMs": null } + ], + "steadyState": [ { "method": "PUT", "path": "/api/me/semester-plans/WiSe%202026%2F27", "observedStatus": 200, "observedDurationMs": null } ] } diff --git a/load-test/scenario.js b/load-test/scenario.js index 370bb71..6d2fe4b 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -8,11 +8,17 @@ * - load-test/sessions.json (node load-test/mint-sessions.mjs) * - load-test/recorded-session.json (node load-test/build-scenario.mjs) * - * Targets the Pages origin, not the Worker origin. Requests must pass through - * the Pages Function and its service binding - * (frontend/functions/_shared/proxy.ts) — that is the path where the Pyodide - * cold-start 500s appear. Hitting studyplanner-api.*.workers.dev directly - * bypasses it and cannot reproduce them. + * Targets the Worker origin, because that is what the deployed frontend calls: + * VITE_API_BASE_URL is baked into the Pages build, so browsers go straight to + * studyplanner-api.*.workers.dev and the same-origin /api/* Pages Function is + * not in the user path at all. Verified against the live bundle — see + * docs/load-test-2026-08.md. + * + * Shape of the run: each VU does one expensive first load (the app caches + * catalog, progress and planner data in sessionStorage for 24h), then loops a + * lighter steady state. That mirrors the scenario under test — twenty people + * opening the app at the start of a lecture — rather than sustained traffic no + * real user generates. */ import http from 'k6/http' @@ -21,7 +27,7 @@ import { Counter, Trend } from 'k6/metrics' import { scenario } from 'k6/execution' const AUTH_COOKIE_NAME = 'studyplanner_session' -const DEFAULT_ORIGIN = 'https://studyplaner.pages.dev' +const DEFAULT_ORIGIN = 'https://studyplanner-api.ben-tischberger.workers.dev' // Think time between steps. A hot loop is not a user simulation: it changes // both the arrival pattern and how many isolates the requests fan across, @@ -32,7 +38,7 @@ const MAX_THINK_SECONDS = 8 const sessionsFile = JSON.parse(open('./sessions.json')) const recording = JSON.parse(open('./recorded-session.json')) -const ORIGIN = (__ENV.LOADTEST_ORIGIN || sessionsFile.origin || DEFAULT_ORIGIN).replace(/\/$/, '') +const ORIGIN = (__ENV.LOADTEST_ORIGIN || recording.apiOrigin || DEFAULT_ORIGIN).replace(/\/$/, '') // The finding we care about is 5xx, and an average hides a handful of them. const serverErrors = new Counter('server_errors') @@ -71,8 +77,11 @@ export function setup() { 'See load-test/README.md.', ) } - console.log(`[scenario] origin=${ORIGIN} steps=${recording.steps.length} sessions=${sessionsFile.sessions.length}`) - return { stepCount: recording.steps.length } + console.log( + `[scenario] origin=${ORIGIN} firstLoad=${recording.firstLoad.length} ` + + `steadyState=${recording.steadyState.length} sessions=${sessionsFile.sessions.length}`, + ) + return { firstLoadSteps: recording.firstLoad.length } } function thinkTime() { @@ -125,14 +134,15 @@ function collectCourseIds(response) { } } -export default function runUserSession() { - const session = pickSession() - let courseIds = [] +// Course ids survive across a VU's iterations, the way a browser keeps the +// cached catalog after the first load. +let cachedCourseIds = [] - for (const step of recording.steps) { +function runSteps(steps, session) { + for (const step of steps) { const pathWithoutQuery = step.path.split('?')[0] const isWrite = step.method !== 'GET' && step.method !== 'HEAD' - const body = isWrite ? buildWriteBody(courseIds) : null + const body = isWrite ? buildWriteBody(cachedCourseIds) : null const response = http.request(step.method, `${ORIGIN}${step.path}`, body, { headers: buildHeaders(session, step.method), @@ -161,13 +171,26 @@ export default function runUserSession() { }, { endpoint: pathWithoutQuery }) if (pathWithoutQuery === '/api/catalog/courses' && response.status === 200) { - courseIds = collectCourseIds(response) + cachedCourseIds = collectCourseIds(response) } sleep(thinkTime()) } } +export default function runUserSession() { + const session = pickSession() + + // __ITER is per-VU, so iteration 0 is this virtual user's session start: the + // one time the catalog, progress and planner payloads actually cross the + // network. Every later iteration is a returning view served from cache. + if (__ITER === 0) { + runSteps(recording.firstLoad, session) + } + + runSteps(recording.steadyState, session) +} + function counterValue(data, metricName) { const metric = data.metrics[metricName] return metric ? metric.values.count : 0 From dc720c45a4e486885ede5bd9bf4826b5ffd32fa3 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 11:09:37 +0200 Subject: [PATCH 3/8] Reproduce the production 503 and record login CPU cost Session minting hit the failure the stress test was built to look for, before any concurrency was applied: HTTP 503 | Worker exceeded resource limits | ray=a275225218a7dc82-FRA It appeared on the 9th of a strictly sequential run of logins, and the immediate retry succeeded, so it depends on isolate state rather than on the request. The response is a Cloudflare interstitial, not an application error, so clients get no JSON body to act on. wrangler tail puts login at 421-538ms of CPU per request - PBKDF2 at 310,000 iterations under Pyodide, against single-digit milliseconds for a typical Worker request. Recorded in docs/load-test-2026-08.md along with the hypothesis that a cold isolate paying Pyodide init on top of that is what breaches the limit, and what confirming it would take. mint-sessions.mjs needed three fixes to get this far, all of which cost real evidence on the first attempt: - Cloudflare interstitials were truncated to 200 characters of HTML, hiding the error code and Ray ID. It now extracts both. - A single failure aborted the run before sessions.json was written, discarding four already-minted sessions. It now writes partial results, resumes from them, and reports failures at the end. - 5xx responses are retried with backoff, and a 429 waits for the next fixed window instead of being recorded as a failure. Retries consume rate-limit budget, which is itself worth knowing. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 52 ++++++++++++- load-test/mint-sessions.mjs | 141 ++++++++++++++++++++++++++++++++---- 2 files changed, 178 insertions(+), 15 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 63a06b1..4562777 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -155,7 +155,57 @@ Expected pressure points, from reading the code: ## Phase D — login burst -_Not run. Record here: 8 simultaneous login timings, and whether they serialise._ +_Formal burst not run yet. But the failure it was meant to look for already +reproduced during session minting, without any concurrency._ + +### The 503 reproduced on sequential logins + +While minting sessions one at a time, login 9 returned: + +``` +HTTP 503 | Worker exceeded resource limits | ray=a275225218a7dc82-FRA +``` + +This is Cloudflare killing the Worker for exceeding its resource budget, not an +application exception — the response is a Cloudflare HTML interstitial, so +clients get no JSON error body. + +Three properties worth recording: + +- **No concurrency was involved.** The requests were strictly sequential. +- **It is intermittent.** The immediate retry succeeded. So it depends on + isolate state or load, not on the request itself. +- **Retries consume rate-limit budget.** 9 logins plus 1 retry hit the + 10-per-15-minute ceiling, which makes the Phase A shared-IP problem worse + than the raw policy numbers suggest. + +### Login costs ~0.5 s of CPU + +`wrangler tail` on the *successful* logins: + +| Request | wallTime | cpuTime | +| --- | --- | --- | +| login 1 | 1005 ms | 529 ms | +| login 2 | 701 ms | 538 ms | +| login 3 | 566 ms | 457 ms | +| login 4 | 523 ms | 421 ms | + +That is `_hash_password` running PBKDF2-HMAC-SHA256 at +`PASSWORD_PBKDF2_ITERATIONS = 310_000` +([`authentication.py:15`](../backend/src/services/authentication.py)) inside +Pyodide. A typical Worker request costs single-digit milliseconds. + +**Working hypothesis (not yet confirmed):** a warm isolate absorbs the ~500 ms, +but a login landing on a cold isolate also pays Pyodide initialisation, and the +two together breach the limit. This is consistent with the Phase 0 cold/warm gap +(12.7 s vs 3.3 s). Confirming it needs the exception text from +`wrangler tail --status error` on a failing request. + +If confirmed, the fix is not a load-balancing or scaling change — it is reducing +the per-login CPU cost. Options to weigh: lowering the iteration count (weakens +password hashing), or moving the hash to WebCrypto's native +`crypto.subtle.deriveBits`, which is not subject to the Python interpreter's +overhead and would need a migration path for existing stored hashes. --- diff --git a/load-test/mint-sessions.mjs b/load-test/mint-sessions.mjs index fd0ac16..1a625f3 100644 --- a/load-test/mint-sessions.mjs +++ b/load-test/mint-sessions.mjs @@ -20,7 +20,7 @@ * cookies. Treat it as a credential file. */ -import { writeFileSync } from 'node:fs' +import { existsSync, readFileSync, writeFileSync } from 'node:fs' import { fileURLToPath } from 'node:url' import { dirname, join } from 'node:path' @@ -38,6 +38,9 @@ const LOGIN_LIMIT_PER_WINDOW = 10 // push the batch over the limit. const LOGINS_PER_BATCH = LOGIN_LIMIT_PER_WINDOW - 1 +const LOGIN_ATTEMPTS = 3 +const RETRY_BACKOFF_SECONDS = 5 + function parseArguments(argv) { const args = { origin: DEFAULT_ORIGIN, count: DEFAULT_COUNT } for (let index = 0; index < argv.length; index += 1) { @@ -80,6 +83,30 @@ function sleep(seconds) { }) } +/** + * A failing Worker returns a Cloudflare HTML interstitial, not the app's JSON + * error. Truncating that HTML hides the only two useful facts in it: the + * Cloudflare error code (1101 = Worker threw, 1102 = CPU limit exceeded, + * 1015 = rate limited) and the Ray ID needed to correlate with `wrangler tail`. + */ +function describeGatewayFailure(status, bodyText, headers) { + const errorCode = bodyText.match(/Error\s*(\d{4})/)?.[1] + const rayId = headers.get('cf-ray') ?? bodyText.match(/Ray ID:\s*<\/span>\s*]*>([0-9a-f]+)/i)?.[1] + const summary = bodyText.match(/]*>(.*?)<\/h2>/s)?.[1].replace(/<[^>]+>/g, '').trim() + + const parts = [`HTTP ${status}`] + if (errorCode) { + parts.push(`Cloudflare error ${errorCode}`) + } + if (summary) { + parts.push(summary) + } + if (rayId) { + parts.push(`ray=${rayId}`) + } + return parts.join(' | ') +} + async function login(origin, username, password) { const response = await fetch(`${origin}/api/auth/login`, { method: 'POST', @@ -93,7 +120,11 @@ async function login(origin, username, password) { throw new Error(`rate limited (429) for ${username}; retry after the next 15-minute window`) } if (!response.ok) { - throw new Error(`login failed for ${username}: ${response.status} ${bodyText.slice(0, 200)}`) + const isHtml = bodyText.trimStart().startsWith('<') + const detail = isHtml + ? describeGatewayFailure(response.status, bodyText, response.headers) + : `${response.status} ${bodyText.slice(0, 200)}` + throw new Error(`login failed for ${username}: ${detail}`) } const sessionCookie = extractSessionCookie(response.headers.getSetCookie()) @@ -109,6 +140,51 @@ async function login(origin, username, password) { return { username, sessionCookie, csrfToken: payload.csrfToken } } +async function waitForNextWindow(reason) { + const waitSeconds = secondsUntilNextWindow() + console.log(`[mint] ${reason} — waiting ${waitSeconds}s for the next window ...`) + await sleep(waitSeconds) +} + +function readExistingSessions(origin) { + if (!existsSync(OUTPUT_PATH)) { + return [] + } + try { + const parsed = JSON.parse(readFileSync(OUTPUT_PATH, 'utf8')) + if (parsed.origin !== origin || !Array.isArray(parsed.sessions)) { + return [] + } + return parsed.sessions + } catch { + return [] + } +} + +/** + * A 5xx here is the behaviour under investigation, not just noise, so each + * attempt is logged rather than silently swallowed. Retrying distinguishes a + * transient blip from a Worker that reliably fails on this request. + */ +async function loginWithRetry(origin, username, password) { + let lastError + for (let attempt = 1; attempt <= LOGIN_ATTEMPTS; attempt += 1) { + try { + return await login(origin, username, password) + } catch (error) { + lastError = error + if (error.message.includes('rate limited')) { + throw error + } + if (attempt < LOGIN_ATTEMPTS) { + console.warn(`[mint] ${username} attempt ${attempt}/${LOGIN_ATTEMPTS} failed: ${error.message}`) + await sleep(RETRY_BACKOFF_SECONDS * attempt) + } + } + } + throw lastError +} + async function main() { const args = parseArguments(process.argv.slice(2)) const password = (process.env.LOADTEST_PASSWORD ?? '').trim() @@ -119,22 +195,50 @@ async function main() { } const usernames = Array.from({ length: args.count }, (_, index) => ACCOUNT_TEMPLATE(index + 1)) - const sessions = [] - console.log(`[mint] ${usernames.length} accounts against ${args.origin}`) + // Resume from a previous partial run. Logins are a scarce resource here + // (10 per 15 minutes per IP), so already-minted sessions are not re-spent. + const sessions = readExistingSessions(args.origin) + const alreadyMinted = new Set(sessions.map((session) => session.username)) + if (alreadyMinted.size > 0) { + console.log(`[mint] resuming — ${alreadyMinted.size} session(s) already in ${OUTPUT_PATH}`) + } + + const pending = usernames.filter((username) => !alreadyMinted.has(username)) + const failures = [] + + console.log(`[mint] ${pending.length} account(s) to mint against ${args.origin}`) console.log(`[mint] batches of ${LOGINS_PER_BATCH} per ${LOGIN_WINDOW_SECONDS / 60}-minute window`) - for (let index = 0; index < usernames.length; index += 1) { - if (index > 0 && index % LOGINS_PER_BATCH === 0) { - const waitSeconds = secondsUntilNextWindow() - console.log(`[mint] login window full — waiting ${waitSeconds}s for the next window ...`) - await sleep(waitSeconds) + let loginsThisWindow = 0 + let index = 0 + while (index < pending.length) { + if (loginsThisWindow >= LOGINS_PER_BATCH) { + await waitForNextWindow('login window full') + loginsThisWindow = 0 } - const username = usernames[index] - const session = await login(args.origin, username, password) - sessions.push(session) - console.log(`[mint] ${index + 1}/${usernames.length} ${username}`) + const username = pending[index] + try { + const session = await loginWithRetry(args.origin, username, password) + sessions.push(session) + console.log(`[mint] ${sessions.length}/${usernames.length} ${username}`) + } catch (error) { + if (error.message.includes('rate limited')) { + // The window budget was already partly spent before this run started + // (failed attempts count too). Wait it out and retry the same account + // rather than burning it as a failure. + await waitForNextWindow('hit the rate limit') + loginsThisWindow = 0 + continue + } + // Keep going: a partial set still lets the run proceed at lower VU count, + // and the failure list is itself a result worth reporting. + failures.push({ username, error: error.message }) + console.error(`[mint] FAILED ${username}: ${error.message}`) + } + loginsThisWindow += 1 + index += 1 } writeFileSync( @@ -142,8 +246,17 @@ async function main() { `${JSON.stringify({ origin: args.origin, mintedAt: new Date().toISOString(), sessions }, null, 2)}\n`, 'utf8', ) - console.log(`[mint] wrote ${OUTPUT_PATH} (${sessions.length} sessions)`) + console.log(`[mint] wrote ${OUTPUT_PATH} (${sessions.length}/${usernames.length} sessions)`) console.log('[mint] this file contains live session cookies — it is gitignored, do not share it') + + if (failures.length > 0) { + console.error(`\n[mint] ${failures.length} account(s) failed after ${LOGIN_ATTEMPTS} attempts each:`) + for (const { username, error } of failures) { + console.error(` ${username}: ${error}`) + } + console.error('[mint] re-run to retry only the missing accounts.') + process.exitCode = 1 + } } main().catch((error) => { From b04dfb1db6cfbfed9ca326dc35402576a68d9e3e Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 13:00:32 +0200 Subject: [PATCH 4/8] Identify the production 500s as a Pyodide GIL fault, not CPU pressure wrangler tail over the full minting run plus concurrent browser traffic captured 43 failing requests, and they are two separate bugs rather than one. The dominant mode, 20 of 43, is "Attempted to use PyProxy when Python GIL not held" - the known workerd Python-Workers defect. Its shape is the giveaway: median CPU of 2ms against a 2.5s wall time. These requests are not exhausting a budget, the Python event loop wedges (Exception in callback PyodideTask.task_wakeup), the request never completes, and Cloudflare kills it and reports exceededCpu. The exceededCpu outcome is a symptom, not the cause. It hits every endpoint and is not load-dependent. This corrects a prior assumption: the fault was believed to be specific to the Pages service-binding path. Every observation here is on direct workers.dev ingress, so switching ingress does not avoid it. The second mode is genuine CPU exhaustion from PBKDF2 at 310,000 iterations, 421-538ms of CPU per login. Real, but only 2 of 43 and confined to /api/auth/login. Two further findings recorded: - 24 of the 43 failures were POST /api/client-errors. When the Worker fails the browser reports each failure to the same wedged Worker, so a partial outage becomes a self-sustaining request storm. - Login 429s while registration keeps working because each policy has its own counter and no other endpoint is rate limited at all. That part is by design. The compounding part is not: enforce_rate_limit runs before authentication, so failed attempts count, and 5xx-driven retries lock users out for 15 minutes through no fault of their own. Phase D is superseded - the 500s reproduced with no concurrency at all. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 92 ++++++++++++++++++++++++++++++++------- 1 file changed, 76 insertions(+), 16 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 4562777..68a501c 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -15,14 +15,25 @@ its design live in [`load-test/README.md`](../load-test/README.md). | Phase | What it establishes | Status | | --- | --- | --- | -| 0 — live reconnaissance | Which origin users actually hit; single-user latency | **Done (2026-08-07, anonymous)** | -| A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | Confirmed by code reading; live check pending | +| 0 — live reconnaissance | Which origin users actually hit; single-user latency | **Done (2026-08-07)** | +| A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | **Done — confirmed live** | | B — baseline | Uncontended per-endpoint latency, authenticated | Not run | | C — 20 concurrent users | 5xx under isolate fan-out; p95 under load | Not run | -| D — login burst | How CPU-bound logins queue | Not run | +| D — login burst | How CPU-bound logins queue | **Superseded — the 500s reproduced without concurrency** | -Phases B–D need the one-time setup in the harness README (seed accounts, record -an authenticated session, mint sessions). +### Bottom line so far + +The production 500s are **not a concurrency problem**. They reproduced during +plain sequential session minting, and the dominant cause is a Pyodide runtime +fault (`Attempted to use PyProxy when Python GIL not held`) that is not +load-dependent at all. Phase C would quantify how often it bites under load, but +it will not change the diagnosis or the fix. + +### Setup state + +Accounts seeded and 20 sessions minted (`load-test/sessions.json`, gitignored, +valid 30 days). Phases B–C additionally need a recorded authenticated session — +`load-test/recorded-session.json` is still a partial placeholder. --- @@ -195,17 +206,66 @@ That is `_hash_password` running PBKDF2-HMAC-SHA256 at ([`authentication.py:15`](../backend/src/services/authentication.py)) inside Pyodide. A typical Worker request costs single-digit milliseconds. -**Working hypothesis (not yet confirmed):** a warm isolate absorbs the ~500 ms, -but a login landing on a cold isolate also pays Pyodide initialisation, and the -two together breach the limit. This is consistent with the Phase 0 cold/warm gap -(12.7 s vs 3.3 s). Confirming it needs the exception text from -`wrangler tail --status error` on a failing request. - -If confirmed, the fix is not a load-balancing or scaling change — it is reducing -the per-login CPU cost. Options to weigh: lowering the iteration count (weakens -password hashing), or moving the hash to WebCrypto's native -`crypto.subtle.deriveBits`, which is not subject to the Python interpreter's -overhead and would need a migration path for existing stored hashes. +### Confirmed: there are TWO separate failure modes + +`wrangler tail --status error` over the full minting run plus concurrent real +browser traffic captured 43 failing requests. They are not one bug. + +| | Mode A — CPU exhaustion | Mode B — Pyodide GIL fault | +| --- | --- | --- | +| Exception | `Worker exceeded CPU time limit.` | `Attempted to use PyProxy when Python GIL not held` | +| Occurrences | 2 | 20 (+3 `code had hung`) | +| cpuTime | 421–538 ms | 0–20 ms (median 2 ms) | +| wallTime | ~500 ms | 2.2–2.8 s | +| Endpoint | `/api/auth/login` only | every endpoint | +| Trigger | PBKDF2 at 310k iterations | not load-dependent | + +**Mode B is the one that matters, and it is the source of the production 500s.** +`Attempted to use PyProxy when Python GIL not held` is the known workerd +Python-Workers defect. Note the shape: median CPU of **2 ms** with a 2.5 s wall +time. These requests are not doing work and running out of budget — the Python +event loop wedges (`Exception in callback PyodideTask.task_wakeup()`), +the request never completes, and Cloudflare eventually kills it and reports +`exceededCpu`. **The `exceededCpu` outcome is misleading**; it is a symptom of +the hang, not CPU pressure. + +One correction to prior notes: this was believed to be specific to the Pages +service-binding path. It is not. Every observation here is on direct +`workers.dev` ingress, so moving to direct ingress does not avoid it. + +Mode A is real but rare and confined to login. Fixing it means reducing +per-login CPU: lower the iteration count (weakens hashing), or move to +WebCrypto's native `crypto.subtle.deriveBits`, which needs a migration path for +existing stored hashes. + +### `/api/client-errors` amplifies the failure + +24 of the 43 failing requests were `POST /api/client-errors` — the frontend's +own error reporter. When the Worker starts failing, the browser reports each +failure, those reports hit the same wedged Worker and fail too. A partial outage +becomes a self-sustaining request storm against the endpoint least able to +absorb it. + +### Why "too many requests" appears on login and nowhere else + +Only five endpoints have any rate limit +([`request_rate_limit.py:19-23`](../backend/src/services/request_rate_limit.py)), +and each policy has its **own** counter keyed by `(scope, client_key)`: + +- `/api/auth/login` — 10 / 15 min +- `/api/auth/register` — 5 / hour, a **separate bucket**, which is why + registering still works when login is locked out +- `/api/feedback`, `/api/ai/catalog/*`, `/api/client-errors` — own buckets + +Everything else — all of `/api/me/*`, the whole catalog — has **no rate limit at +all**. So "login 429s but everything else is fine" is exactly the designed +behaviour, not a fault. + +The compounding effect is the part worth fixing: `enforce_rate_limit` runs +*before* authentication, so **failed attempts count**. Mode B causes 5xx, clients +retry, each retry burns login budget, and users are locked out for 15 minutes by +an outage that was never their fault. During this run, 20 logins plus 3 retries +exhausted two full windows. --- From b5bfcfeb09737b52c22bcdb1ea8d826ec17daedc Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 13:39:36 +0200 Subject: [PATCH 5/8] Fix the two backend faults behind the load-test 500s The August 2026 concurrent-user test surfaced two backend defects and one non-fix. See docs/load-test-2026-08.md for the measurements. Login rate limiting punished the wrong people. Every policy keyed on sha256(CF-Connecting-IP), so twenty students behind one campus NAT shared a budget of 10 logins per 15 minutes and users 11-20 got 429. Worse, enforce_rate_limit ran before authentication, so a 5xx from a wedged isolate and every retry it provoked consumed the same budget as a wrong password: an outage locked users out for the rest of the window. auth_login is now keyed on the submitted account and split into a read (enforce_failed_attempt_limit) and a write (record_failed_attempt) that only fires on a genuine AuthenticationError. Successful logins and server-side failures cost nothing. Keying on the account would normally invite a targeted lockout; counting only failures is what removes that, because a user with the right password never touches the counter. The ceiling is raised to 500 per 15 minutes, and registration to 50 per hour - a deliberate call that frustrated users are the likelier harm here. Password hashing ran PBKDF2-HMAC-SHA256 at 310,000 iterations through hashlib, i.e. as interpreted Pyodide bytecode, costing 421-538 ms of CPU per login and failing outright with "Worker exceeded CPU time limit". password_hashing.py derives the same digest natively through crypto.subtle.deriveBits, with hashlib kept as a fallback so a broken fast path degrades into slow logins rather than failed ones. No hash migration is needed: same algorithm, salt and iteration count give byte-identical output, verified in the runtime rather than argued from the spec. Raising compatibility_date to 2026-04-01 was tried as a candidate fix for the Pyodide GIL fault (cloudflare/workerd#6624) and reverted - it failed 60/60 requests with a dedicated-snapshot error and flips entrypoint dispatch from on_fetch to fetch. That fault stays open upstream. Co-Authored-By: Claude Opus 5 --- AGENTS.md | 1 + backend/scripts/seed_load_test_users.py | 13 ++- backend/src/main.py | 3 + backend/src/password_hashing.py | 93 +++++++++++++++ backend/src/router.py | 20 +++- backend/src/services/authentication.py | 40 ++++--- backend/src/services/request_rate_limit.py | 130 ++++++++++++++++++--- backend/tests/test_password_hashing.py | 89 ++++++++++++++ backend/tests/test_request_rate_limit.py | 92 +++++++++++++++ backend/wrangler.toml | 10 ++ load-test/README.md | 30 ++--- 11 files changed, 468 insertions(+), 53 deletions(-) create mode 100644 backend/src/password_hashing.py create mode 100644 backend/tests/test_password_hashing.py diff --git a/AGENTS.md b/AGENTS.md index 15abd8c..054f719 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -49,6 +49,7 @@ Every new frontend feature must work on both phone and desktop. - Current active D1 for deployments is `studyplanner-db` (`80ca9092-ddc6-454a-b04a-8ccae85ef2f5`) through the Worker binding `DB`. The cutover from `studyplaner-db-test` was approved and executed with the `integrate_new_db` branch (multi-period ALMA catalog). - `studyplaner-db-test` (`297f7a28-9069-431d-b989-49acf2537513`) is the previous test database; do not switch the active runtime DB again without explicit human approval. - The D1 database name and UUID are public Cloudflare binding config and may be committed; never commit `AUTH_TOKEN_SECRET` or any generated secret value. +- Do not raise `compatibility_date` in `backend/wrangler.toml` without a cold `wrangler dev --remote` check first. Raising it to `2026-04-01` failed 60/60 requests with a Pyodide snapshot error and flipped entrypoint dispatch from `on_fetch` to `fetch`. Details in that file's comment and `docs/load-test-2026-08.md`. - Run `npm run db:verify-config` before deploys or after touching Cloudflare/Pages config. The GitHub workflow with the same check should be required on `main` branch protection. - To refresh the ALMA catalog, re-seed the existing D1 **in place** — do not create/swap a DB: `py backend/scripts/import_alma_json_to_d1.py --input --apply --skip-create --skip-swap --skip-migrate`. The seed DELETEs all catalog rows and reinserts only the periods present in the JSON, so keep every period you want to retain in the input. See that script's docstring for the D1 remote-import limits (compound-SELECT coalescing, Durable-Object reset) it works around. diff --git a/backend/scripts/seed_load_test_users.py b/backend/scripts/seed_load_test_users.py index e3b8a74..f2b5f43 100644 --- a/backend/scripts/seed_load_test_users.py +++ b/backend/scripts/seed_load_test_users.py @@ -17,8 +17,11 @@ * user_auth — username/email/password_hash/password_salt. The hash format is PBKDF2-HMAC-SHA256 at PASSWORD_PBKDF2_ITERATIONS, hex-encoded, exactly as - _hash_password() computes it. If that constant ever changes, logins for - these accounts break until this script is re-run. + backend/src/password_hashing.py computes it. The Worker derives the same + digest through WebCrypto rather than hashlib, which is byte-for-byte + identical for these parameters — so hashes written here verify there. If the + iteration count ever changes, logins for these accounts break until this + script is re-run. * user_state — display name plus the supported PO 2021 study program and its default regulation version, resolved by subselect. login_user() would backfill a bare user_state row on its own, but seeding the study program @@ -54,8 +57,8 @@ DEFAULT_ACCOUNT_TEMPLATE = "loadtest-{index:02d}@example.com" # Must stay in sync with PASSWORD_PBKDF2_ITERATIONS in -# backend/src/services/authentication.py — a mismatch produces accounts that -# exist but can never log in. +# backend/src/password_hashing.py — a mismatch produces accounts that exist but +# can never log in. PASSWORD_PBKDF2_ITERATIONS = 310_000 # Mirrors SUPPORTED_REGULATION_SOURCE_STATUS / SUPPORTED_REGULATION_PO_VERSION. @@ -64,7 +67,7 @@ def hash_password(password: str, salt_hex: str) -> str: - """Hash exactly as authentication._hash_password does.""" + """Hash exactly as password_hashing.hash_password_hex does.""" password_hash = hashlib.pbkdf2_hmac( "sha256", password.encode("utf-8"), diff --git a/backend/src/main.py b/backend/src/main.py index 5c6b011..2e9d4e5 100644 --- a/backend/src/main.py +++ b/backend/src/main.py @@ -10,5 +10,8 @@ class Default(WorkerEntrypoint): """Cloudflare Worker entry point for the StudyPlanner API.""" + # Must stay `on_fetch` at the compatibility date pinned in wrangler.toml. + # Later dates dispatch to `fetch` instead, which is one of the reasons the + # bump was reverted — see the comment there. async def on_fetch(self, request: Any) -> Any: return await route_request(request, self.env) diff --git a/backend/src/password_hashing.py b/backend/src/password_hashing.py new file mode 100644 index 0000000..c9f1e68 --- /dev/null +++ b/backend/src/password_hashing.py @@ -0,0 +1,93 @@ +"""PBKDF2 password hashing, run by the runtime's native WebCrypto where available. + +`hashlib.pbkdf2_hmac` executes all 310,000 iterations as interpreted Pyodide +bytecode. Measured against production that cost 421-538 ms of CPU per login, +which is most of a Worker's budget for a single request and was enough to make +`/api/auth/login` fail outright with "Worker exceeded CPU time limit". It also +holds the interpreter for that whole stretch, which widens the window for the +Pyodide GIL race that wedges concurrent requests (cloudflare/workerd#6624). + +`crypto.subtle.deriveBits` computes the same PBKDF2-HMAC-SHA256 natively: same +salt, same iteration count, same 32-byte output. Stored hashes therefore stay +valid and no migration is needed — this is purely a change of executor. + +`hashlib` stays as the fallback so unit tests (no JS bridge) and any runtime +without WebCrypto keep working, and so a broken fast path degrades into slow +logins rather than failed ones. +""" + +from __future__ import annotations + +from typing import Any + +import hashlib + +PASSWORD_PBKDF2_ITERATIONS = 310_000 +DERIVED_KEY_BITS = 256 + +# Resolved on first use. The JS bridge either exists for the lifetime of an +# isolate or it does not, so probing once avoids paying an import failure on +# every request under the fallback. +_webcrypto_usable: bool | None = None + + +def hash_password_with_hashlib(password: str, salt_bytes: bytes, iterations: int) -> bytes: + return hashlib.pbkdf2_hmac('sha256', password.encode('utf-8'), salt_bytes, iterations) + + +def _to_js_bytes(data: bytes) -> Any: + from js import Uint8Array + + buffer = Uint8Array.new(len(data)) + buffer.assign(data) + return buffer + + +async def _hash_password_with_webcrypto(password: str, salt_bytes: bytes, iterations: int) -> bytes: + from js import Object, Uint8Array, crypto + from pyodide.ffi import to_js + + key = await crypto.subtle.importKey( + 'raw', + _to_js_bytes(password.encode('utf-8')), + 'PBKDF2', + False, + to_js(['deriveBits']), + ) + derived_bits = await crypto.subtle.deriveBits( + to_js( + { + 'name': 'PBKDF2', + 'salt': _to_js_bytes(salt_bytes), + 'iterations': iterations, + 'hash': 'SHA-256', + }, + dict_converter=Object.fromEntries, + ), + key, + DERIVED_KEY_BITS, + ) + return Uint8Array.new(derived_bits).to_bytes() + + +async def hash_password_hex( + password: str, + salt_hex: str, + iterations: int = PASSWORD_PBKDF2_ITERATIONS, +) -> str: + """Return the hex PBKDF2-HMAC-SHA256 digest of a password for a given salt.""" + global _webcrypto_usable + + salt_bytes = bytes.fromhex(salt_hex) + if _webcrypto_usable is not False: + try: + digest = await _hash_password_with_webcrypto(password, salt_bytes, iterations) + _webcrypto_usable = True + return digest.hex() + except Exception as exc: # noqa: BLE001 - any failure must degrade, not 500 + _webcrypto_usable = False + # Surfaces in `wrangler tail`: logins still work, but slowly, and + # the CPU-limit failures this change exists to remove will return. + print(f'[auth] WebCrypto PBKDF2 unavailable, falling back to hashlib: {exc}') + + return hash_password_with_hashlib(password, salt_bytes, iterations).hex() diff --git a/backend/src/router.py b/backend/src/router.py index 8f0c762..eea7431 100644 --- a/backend/src/router.py +++ b/backend/src/router.py @@ -23,6 +23,7 @@ get_current_user_profile, login_user, logout_user, + read_login_identifier, register_user, require_csrf_protection, update_current_user_profile, @@ -52,7 +53,9 @@ CLIENT_ERROR_POLICY, FEEDBACK_POLICY, RateLimitError, + enforce_failed_attempt_limit, enforce_rate_limit, + record_failed_attempt, ) from services.user_feedback import FeedbackSubmissionError, submit_feedback from services.planner_assignments import ( @@ -324,8 +327,21 @@ async def route_request(request: Any, env: Any) -> Any: if method != "POST": return _method_not_allowed_response(request, env) - await enforce_rate_limit(env, request, AUTH_LOGIN_POLICY) - auth_payload = await login_user(env, await read_json_object(request), request) + login_payload = await read_json_object(request) + login_identifier = read_login_identifier(login_payload) + await enforce_failed_attempt_limit( + env, request, AUTH_LOGIN_POLICY, identifier=login_identifier + ) + try: + auth_payload = await login_user(env, login_payload, request) + except AuthenticationError: + # Only a genuinely wrong credential costs budget. A 5xx from a + # wedged isolate, and the retries it provokes, must not lock the + # account out of an outage it did not cause. + await record_failed_attempt( + env, request, AUTH_LOGIN_POLICY, identifier=login_identifier + ) + raise return _new_session_response(auth_payload, request, env) if path == "/api/auth/logout": diff --git a/backend/src/services/authentication.py b/backend/src/services/authentication.py index 31e4fb1..1ee555b 100644 --- a/backend/src/services/authentication.py +++ b/backend/src/services/authentication.py @@ -10,9 +10,9 @@ from db.d1 import execute, fetch_one from env_config import get_env_value from http_utils import get_request_header +from password_hashing import PASSWORD_PBKDF2_ITERATIONS, hash_password_hex from services.user_data import dumps_json, ensure_user_progress, ensure_user_state, now_unix, parse_json_object -PASSWORD_PBKDF2_ITERATIONS = 310_000 DEFAULT_AUTH_TOKEN_TTL_SECONDS = 30 * 24 * 60 * 60 AUTH_TOKEN_MAX_CLOCK_SKEW_SECONDS = 60 AUTH_COOKIE_NAME = 'studyplanner_session' @@ -89,20 +89,13 @@ def _get_auth_token_secret(env: Any) -> str: return token_secret -def _hash_password(password: str, salt_hex: str) -> str: - salt_bytes = bytes.fromhex(salt_hex) - password_hash = hashlib.pbkdf2_hmac( - 'sha256', - password.encode('utf-8'), - salt_bytes, - PASSWORD_PBKDF2_ITERATIONS, - ) - return password_hash.hex() +async def _hash_password(password: str, salt_hex: str) -> str: + return await hash_password_hex(password, salt_hex, PASSWORD_PBKDF2_ITERATIONS) -def _create_password_hash(password: str) -> tuple[str, str]: +async def _create_password_hash(password: str) -> tuple[str, str]: salt_hex = secrets.token_hex(16) - return _hash_password(password, salt_hex), salt_hex + return await _hash_password(password, salt_hex), salt_hex def _base64url_encode(value: bytes) -> str: @@ -484,7 +477,7 @@ async def register_user(env: Any, payload: dict[str, Any], request: Any) -> dict if email != username and await _get_user_by_identifier(env, email) is not None: raise RegistrationError('An account already exists for this email or username.') - password_hash, password_salt = _create_password_hash(password) + password_hash, password_salt = await _create_password_hash(password) current_unix = now_unix() await execute( @@ -561,19 +554,28 @@ async def register_user(env: Any, payload: dict[str, Any], request: Any) -> dict } -async def login_user(env: Any, payload: dict[str, Any], request: Any) -> dict[str, Any]: - del request +def read_login_identifier(payload: dict[str, Any]) -> Any: + """Return the account a login body is aimed at, whichever field carries it. + + The router needs the same answer as login_user so that failed attempts are + charged against the account actually being tried, not against a fallback key. + """ raw_identifier = payload.get('identifier') if raw_identifier in (None, ''): raw_identifier = payload.get('email') or payload.get('username') - identifier = _validate_login_identifier(_safe_text(raw_identifier)) + return raw_identifier + + +async def login_user(env: Any, payload: dict[str, Any], request: Any) -> dict[str, Any]: + del request + identifier = _validate_login_identifier(_safe_text(read_login_identifier(payload))) password = _validate_password(payload.get('password')) user_row = await _get_user_by_identifier(env, identifier) if user_row is None: raise AuthenticationError('Invalid credentials.') - expected_hash = _hash_password(password, str(user_row['passwordSalt'])) + expected_hash = await _hash_password(password, str(user_row['passwordSalt'])) if not hmac.compare_digest(str(user_row['passwordHash']), expected_hash): raise AuthenticationError('Invalid credentials.') @@ -897,7 +899,7 @@ async def update_user_credentials( if user_row is None: raise CredentialUpdateError('User not found.') - expected_hash = _hash_password(current_password, str(user_row['passwordSalt'])) + expected_hash = await _hash_password(current_password, str(user_row['passwordSalt'])) if not hmac.compare_digest(str(user_row['passwordHash']), expected_hash): raise CredentialUpdateError('Current password is incorrect.') @@ -918,7 +920,7 @@ async def update_user_credentials( new_password = _validate_password(payload.get('newPassword')) except RegistrationError as exc: raise CredentialUpdateError(str(exc)) from exc - pw_hash, pw_salt = _create_password_hash(new_password) + pw_hash, pw_salt = await _create_password_hash(new_password) auth_updates['password_hash'] = pw_hash auth_updates['password_salt'] = pw_salt diff --git a/backend/src/services/request_rate_limit.py b/backend/src/services/request_rate_limit.py index 54ad5ff..70468a3 100644 --- a/backend/src/services/request_rate_limit.py +++ b/backend/src/services/request_rate_limit.py @@ -16,8 +16,12 @@ class RateLimitPolicy: window_seconds: int -AUTH_LOGIN_POLICY = RateLimitPolicy('auth_login', maximum_requests=10, window_seconds=15 * 60) -AUTH_REGISTRATION_POLICY = RateLimitPolicy('auth_registration', maximum_requests=5, window_seconds=60 * 60) +# Login is limited per account and counts only failed attempts, so the ceiling +# exists to slow password guessing rather than to shape traffic. It is kept +# deliberately high: locking out a whole lecture hall behind one campus NAT is a +# far more likely outcome than an actual brute-force attempt. +AUTH_LOGIN_POLICY = RateLimitPolicy('auth_login', maximum_requests=500, window_seconds=15 * 60) +AUTH_REGISTRATION_POLICY = RateLimitPolicy('auth_registration', maximum_requests=50, window_seconds=60 * 60) FEEDBACK_POLICY = RateLimitPolicy('feedback', maximum_requests=5, window_seconds=60 * 60) AI_CATALOG_POLICY = RateLimitPolicy('ai_catalog', maximum_requests=30, window_seconds=60) CLIENT_ERROR_POLICY = RateLimitPolicy('client_error', maximum_requests=30, window_seconds=60 * 60) @@ -37,20 +41,36 @@ def _client_key(request: Any) -> str: return hashlib.sha256(client_ip.encode('utf-8')).hexdigest() +def _account_key(request: Any, identifier: Any) -> str: + """Return a non-reversible storage key for the account being signed into. + + Keying failed logins on the account rather than the client IP is what keeps + twenty students behind one campus NAT independent of each other. The prefix + keeps this key space disjoint from _client_key's. + """ + normalized_identifier = str(identifier or '').strip().lower() + if not normalized_identifier: + # A request with no identifier can never authenticate; fall back to the + # IP so a flood of malformed bodies is still bounded. + return _client_key(request) + return hashlib.sha256(f'account:{normalized_identifier}'.encode('utf-8')).hexdigest() + + def _window_start(now_unix: int, window_seconds: int) -> int: return now_unix - (now_unix % window_seconds) -async def enforce_rate_limit( +def _retry_after_seconds(window_start_unix: int, policy: RateLimitPolicy, current_unix: int) -> int: + return max(1, window_start_unix + policy.window_seconds - current_unix) + + +async def _increment_window( env: Any, - request: Any, policy: RateLimitPolicy, - *, - now_unix: int | None = None, -) -> None: - """Atomically record a request and reject it once its fixed window is full.""" - current_unix = int(time.time()) if now_unix is None else now_unix - window_start_unix = _window_start(current_unix, policy.window_seconds) + client_key: str, + window_start_unix: int, +) -> int: + """Atomically add one request to the window and return the new count.""" row = await fetch_one( env, """ @@ -65,9 +85,91 @@ async def enforce_rate_limit( END RETURNING request_count AS requestCount """, - [policy.scope, _client_key(request), window_start_unix], + [policy.scope, client_key, window_start_unix], ) - request_count = int(row.get('requestCount', 0)) if row else 0 + return int(row.get('requestCount', 0)) if row else 0 + + +async def _read_window_count( + env: Any, + policy: RateLimitPolicy, + client_key: str, + window_start_unix: int, +) -> int: + """Return the count already recorded for this window, ignoring stale windows.""" + row = await fetch_one( + env, + """ + SELECT request_count AS requestCount + FROM request_rate_limits + WHERE scope = ? AND client_key = ? AND window_started_at_unix = ? + """, + [policy.scope, client_key, window_start_unix], + ) + return int(row.get('requestCount', 0)) if row else 0 + + +async def enforce_rate_limit( + env: Any, + request: Any, + policy: RateLimitPolicy, + *, + now_unix: int | None = None, +) -> None: + """Atomically record a request and reject it once its fixed window is full. + + Every call costs budget, so this suits volume limits (feedback, AI, client + error reports) where the request itself is the thing being bounded. Login + uses the failed-attempt pair below instead. + """ + current_unix = int(time.time()) if now_unix is None else now_unix + window_start_unix = _window_start(current_unix, policy.window_seconds) + request_count = await _increment_window(env, policy, _client_key(request), window_start_unix) if request_count > policy.maximum_requests: - retry_after_seconds = max(1, window_start_unix + policy.window_seconds - current_unix) - raise RateLimitError(retry_after_seconds) + raise RateLimitError(_retry_after_seconds(window_start_unix, policy, current_unix)) + + +async def enforce_failed_attempt_limit( + env: Any, + request: Any, + policy: RateLimitPolicy, + *, + identifier: Any, + now_unix: int | None = None, +) -> None: + """Reject a login only once the account's window is full of failed attempts. + + This read is deliberately non-charging. Attempts were previously counted + before authentication ran, so a server-side 5xx — and every client retry it + provoked — burned the same budget as a wrong password, and an outage locked + users out for the rest of the window. Pair it with record_failed_attempt(). + """ + current_unix = int(time.time()) if now_unix is None else now_unix + window_start_unix = _window_start(current_unix, policy.window_seconds) + failure_count = await _read_window_count( + env, + policy, + _account_key(request, identifier), + window_start_unix, + ) + if failure_count >= policy.maximum_requests: + raise RateLimitError(_retry_after_seconds(window_start_unix, policy, current_unix)) + + +async def record_failed_attempt( + env: Any, + request: Any, + policy: RateLimitPolicy, + *, + identifier: Any, + now_unix: int | None = None, +) -> None: + """Charge one failed authentication against the account's window.""" + current_unix = int(time.time()) if now_unix is None else now_unix + window_start_unix = _window_start(current_unix, policy.window_seconds) + await _increment_window( + env, + policy, + _account_key(request, identifier), + window_start_unix, + ) diff --git a/backend/tests/test_password_hashing.py b/backend/tests/test_password_hashing.py new file mode 100644 index 0000000..84ff528 --- /dev/null +++ b/backend/tests/test_password_hashing.py @@ -0,0 +1,89 @@ +import hashlib +import sys +import types +import unittest +from pathlib import Path +from unittest.mock import AsyncMock, patch + +sys.path.append(str(Path(__file__).resolve().parents[1] / "src")) + +workers = types.ModuleType("workers") +workers.Response = object +sys.modules.setdefault("workers", workers) + +import password_hashing # noqa: E402 + + +class PasswordHashingTest(unittest.IsolatedAsyncioTestCase): + SALT_HEX = "0123456789abcdef0123456789abcdef" + # 310,000 iterations takes seconds in CPython; the equivalence being tested + # is a property of PBKDF2, not of the iteration count. + ITERATIONS = 1_000 + + def setUp(self) -> None: + password_hashing._webcrypto_usable = None + + def tearDown(self) -> None: + password_hashing._webcrypto_usable = None + + async def test_webcrypto_digest_is_returned_as_hex(self) -> None: + expected = hashlib.pbkdf2_hmac( + "sha256", + b"correct horse", + bytes.fromhex(self.SALT_HEX), + self.ITERATIONS, + ) + derive = AsyncMock(return_value=expected) + + with patch.object(password_hashing, "_hash_password_with_webcrypto", derive): + digest = await password_hashing.hash_password_hex( + "correct horse", self.SALT_HEX, self.ITERATIONS + ) + + self.assertEqual(digest, expected.hex()) + + async def test_falls_back_to_hashlib_when_webcrypto_is_unavailable(self) -> None: + derive = AsyncMock(side_effect=ImportError("no js module")) + + with patch.object(password_hashing, "_hash_password_with_webcrypto", derive): + digest = await password_hashing.hash_password_hex( + "correct horse", self.SALT_HEX, self.ITERATIONS + ) + + self.assertEqual( + digest, + hashlib.pbkdf2_hmac( + "sha256", b"correct horse", bytes.fromhex(self.SALT_HEX), self.ITERATIONS + ).hex(), + ) + + async def test_webcrypto_is_probed_once_and_then_left_alone(self) -> None: + derive = AsyncMock(side_effect=ImportError("no js module")) + + with patch.object(password_hashing, "_hash_password_with_webcrypto", derive): + await password_hashing.hash_password_hex("a", self.SALT_HEX, self.ITERATIONS) + await password_hashing.hash_password_hex("b", self.SALT_HEX, self.ITERATIONS) + + self.assertEqual(derive.await_count, 1) + + async def test_stored_hashes_stay_valid_across_the_two_implementations(self) -> None: + """The whole no-migration claim: both paths must agree byte for byte.""" + salt_bytes = bytes.fromhex(self.SALT_HEX) + stored = password_hashing.hash_password_with_hashlib( + "correct horse", salt_bytes, self.ITERATIONS + ) + # WebCrypto derives 256 bits of PBKDF2-HMAC-SHA256, which is exactly what + # hashlib returns for the same salt and iteration count. + self.assertEqual(len(stored) * 8, password_hashing.DERIVED_KEY_BITS) + + derive = AsyncMock(return_value=stored) + with patch.object(password_hashing, "_hash_password_with_webcrypto", derive): + recomputed = await password_hashing.hash_password_hex( + "correct horse", self.SALT_HEX, self.ITERATIONS + ) + + self.assertEqual(recomputed, stored.hex()) + + +if __name__ == "__main__": + unittest.main() diff --git a/backend/tests/test_request_rate_limit.py b/backend/tests/test_request_rate_limit.py index f32ee5d..fd860ef 100644 --- a/backend/tests/test_request_rate_limit.py +++ b/backend/tests/test_request_rate_limit.py @@ -54,5 +54,97 @@ async def test_request_below_limit_passes(self) -> None: ) +class FailedAttemptLimitTest(unittest.IsolatedAsyncioTestCase): + POLICY = request_rate_limit.RateLimitPolicy('test', maximum_requests=2, window_seconds=60) + + def test_two_accounts_behind_one_ip_get_separate_budgets(self) -> None: + request = Request('198.51.100.10') + + first_key = request_rate_limit._account_key(request, 'ada@example.com') + second_key = request_rate_limit._account_key(request, 'grace@example.com') + + self.assertNotEqual(first_key, second_key) + self.assertNotEqual(first_key, request_rate_limit._client_key(request)) + + def test_account_key_ignores_case_and_surrounding_whitespace(self) -> None: + request = Request('198.51.100.10') + + self.assertEqual( + request_rate_limit._account_key(request, ' Ada@Example.com '), + request_rate_limit._account_key(request, 'ada@example.com'), + ) + + def test_missing_identifier_falls_back_to_the_client_ip(self) -> None: + request = Request('198.51.100.10') + + self.assertEqual( + request_rate_limit._account_key(request, None), + request_rate_limit._client_key(request), + ) + + async def test_checking_the_limit_does_not_consume_budget(self) -> None: + fetch_one = AsyncMock(return_value={'requestCount': 1}) + + with patch.object(request_rate_limit, 'fetch_one', fetch_one): + await request_rate_limit.enforce_failed_attempt_limit( + {}, + Request('198.51.100.10'), + self.POLICY, + identifier='ada@example.com', + now_unix=125, + ) + + # A successful login, or one that 5xx'd inside the Worker, must leave the + # window untouched — so the check may only ever read. + self.assertIn('SELECT', fetch_one.await_args.args[1]) + self.assertNotIn('INSERT', fetch_one.await_args.args[1]) + + async def test_limit_is_reached_once_the_window_is_full_of_failures(self) -> None: + with patch.object(request_rate_limit, 'fetch_one', AsyncMock(return_value={'requestCount': 2})): + with self.assertRaises(request_rate_limit.RateLimitError) as context: + await request_rate_limit.enforce_failed_attempt_limit( + {}, + Request('198.51.100.10'), + self.POLICY, + identifier='ada@example.com', + now_unix=125, + ) + + self.assertEqual(context.exception.retry_after_seconds, 55) + + async def test_recording_a_failure_charges_the_account_window(self) -> None: + request = Request('198.51.100.10') + fetch_one = AsyncMock(return_value={'requestCount': 1}) + + with patch.object(request_rate_limit, 'fetch_one', fetch_one): + await request_rate_limit.record_failed_attempt( + {}, + request, + self.POLICY, + identifier='ada@example.com', + now_unix=125, + ) + + self.assertIn('INSERT', fetch_one.await_args.args[1]) + params = fetch_one.await_args.args[2] + self.assertEqual(params[0], 'test') + self.assertEqual(params[1], request_rate_limit._account_key(request, 'ada@example.com')) + self.assertEqual(params[2], 120) + + async def test_a_stale_window_row_does_not_count_against_the_current_window(self) -> None: + fetch_one = AsyncMock(return_value=None) + + with patch.object(request_rate_limit, 'fetch_one', fetch_one): + await request_rate_limit.enforce_failed_attempt_limit( + {}, + Request('198.51.100.10'), + self.POLICY, + identifier='ada@example.com', + now_unix=125, + ) + + self.assertEqual(fetch_one.await_args.args[2][2], 120) + + if __name__ == '__main__': unittest.main() diff --git a/backend/wrangler.toml b/backend/wrangler.toml index fc27939..5b005b2 100644 --- a/backend/wrangler.toml +++ b/backend/wrangler.toml @@ -1,5 +1,15 @@ name = "studyplanner-api" main = "src/main.py" +# Pyodide and the Python Workers runtime are selected by this date. Do not raise +# it without re-running the check below. +# +# Raising it to 2026-04-01 was tried as a candidate fix for cloudflare/workerd#6624 +# (the GIL fault behind the production 500s — see docs/load-test-2026-08.md) and +# reverted: on a cold `wrangler dev --remote` every request failed 500 with +# PythonWorkersInternalError: Received non-dedicated snapshot but compat flag +# for dedicated snapshots is enabled +# 60/60 requests, no exceptions. It also flips entrypoint dispatch, so local +# `wrangler dev` then wants `fetch` where the deployed runtime wants `on_fetch`. compatibility_date = "2025-05-20" compatibility_flags = ["python_workers"] workers_dev = true diff --git a/load-test/README.md b/load-test/README.md index 4a2a131..c1b817e 100644 --- a/load-test/README.md +++ b/load-test/README.md @@ -7,16 +7,18 @@ run go in `docs/load-test-.md`. Three risks motivated this harness. Only two need a load generator: -1. **Shared-IP rate limiting.** `enforce_rate_limit` keys every policy on - `sha256(CF-Connecting-IP)` (`backend/src/services/request_rate_limit.py:36`). - Login allows 10 requests / 15 min and registration 5 / hour. Twenty students - behind one campus NAT share one key, so users 11–20 get `429`. This needs no - load test — it is arithmetic — but it also constrains how the harness works - (see *pre-minted sessions* below). -2. **Pyodide cold start under isolate fan-out.** Concurrent arrivals spread - across fresh isolates, and Pyodide init has crashed there before. This is the - primary thing the run is looking for, and it only reproduces through the - Pages origin. +1. **Shared-IP rate limiting.** *Confirmed, then fixed* — see + `docs/load-test-2026-08.md`. Login used to allow 10 requests / 15 min keyed on + `sha256(CF-Connecting-IP)`, so twenty students behind one campus NAT shared + one budget and users 11–20 got `429`. Login is now keyed per account, counts + only failed attempts, and allows 500 per 15 min. The remaining volume + policies (feedback, AI catalog, client errors) are still per IP. +2. **The Pyodide GIL fault.** `Attempted to use PyProxy when Python GIL not held` + — [cloudflare/workerd#6624](https://github.com/cloudflare/workerd/issues/6624), + open. This is the source of the production 500s. It needs only 3–5 concurrent + requests, so it is a low-concurrency bug rather than a scale one, and no + change in this repo can fix it. What the run measures now is how often it + bites and whether the frontend's retry hides it. 3. **Sequential D1 round-trips.** `/api/me/progress` issues ~7 sequential queries, the catalog service ~19. Expect p95 to degrade before anything errors. @@ -33,9 +35,11 @@ Four design decisions follow from that: tests an assumption about what the app does. `build-scenario.mjs` derives it from `sessionStorage['studyplanner:api-request-log']`, which the app already maintains (`frontend/src/shared/utils/apiRequestLog.ts`). -- **Sessions are pre-minted.** Logging in inside the test would hit the 10/15min - limit at VU 11 and measure the limiter. `mint-sessions.mjs` collects cookies - out of band; they last 30 days. +- **Sessions are pre-minted.** This predates the limiter fix, when logging in + inside the test would have hit the 10/15min ceiling at VU 11 and measured the + limiter instead of the app. It is still worth keeping: a run that spends its + first 20 iterations on PBKDF2 measures registration cost, not steady-state + traffic. `mint-sessions.mjs` collects cookies out of band; they last 30 days. - **The target is the Worker origin** (`https://studyplanner-api.ben-tischberger.workers.dev`), because that is what the deployed frontend calls. `VITE_API_BASE_URL` is baked into the Pages From 4b8f0a40d014d1ab8eac37301812a6c4e6056cbb Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 13:39:49 +0200 Subject: [PATCH 6/8] Stop a partial backend outage from feeding itself 24 of the 43 failures captured during the load test were POST /api/client-errors - the frontend's own error reporter, failing against the same wedged Worker it was reporting on. A partial outage became a self-sustaining request storm against the endpoint least able to absorb it. fetchJson now retries GET and HEAD up to three times on 5xx and transport failures. The Pyodide GIL fault (cloudflare/workerd#6624) wedges one request and serves the next normally, so most of it becomes latency the user never sees. Mutations are deliberately not retried: a POST that timed out may still have been applied. Every attempt is still written to the local request log, since the retries are themselves a signal, but only the final one is reported upstream - so a recovered blip generates no traffic at all. reportClientErrorToServer additionally caps reports at 10 per page load and drops 401 and 429 outright. Every anonymous visitor's session check is a 401 and a 429 is the limiter working as designed; both arrive in bursts and drown out the reports worth reading. It also no longer reads window.location unguarded. That runs inside fetchJson's failure path, where a ReferenceError would replace the ApiError callers expect. Co-Authored-By: Claude Opus 5 --- frontend/src/shared/utils/api.ts | 185 +++++++++++------- .../src/shared/utils/reportClientError.ts | 35 +++- frontend/tests/shared/apiRetry.test.ts | 102 ++++++++++ 3 files changed, 245 insertions(+), 77 deletions(-) create mode 100644 frontend/tests/shared/apiRetry.test.ts diff --git a/frontend/src/shared/utils/api.ts b/frontend/src/shared/utils/api.ts index 25298b9..9dfed4b 100644 --- a/frontend/src/shared/utils/api.ts +++ b/frontend/src/shared/utils/api.ts @@ -60,99 +60,132 @@ export function createLegacyBearerHeaders(token: string | null | undefined): Hea return { Authorization: `Bearer ${token}` } } +const RETRY_SAFE_METHODS = new Set(['GET', 'HEAD']) +const MAX_ATTEMPTS = 3 +const RETRY_BACKOFF_MS = 300 + +/** + * A Python isolate that faults with the workerd GIL race (cloudflare/workerd#6624) + * hangs that one request and then serves the next one normally, so a single + * retry turns a visible error into a little extra latency. Status 0 is a + * transport failure, which behaves the same way. + * + * Only methods that are safe to repeat are retried; a POST that timed out may + * still have been applied server-side. + */ +export function isRetryableFailure(method: string, status: number): boolean { + return RETRY_SAFE_METHODS.has(method.toUpperCase()) && (status === 0 || status >= 500) +} + +function delay(milliseconds: number): Promise { + return new Promise((resolve) => { + setTimeout(resolve, milliseconds) + }) +} + +interface RequestFailure { + status: number + code?: string + message: string + detail?: string +} + export async function fetchJson(path: string, init?: RequestInit): Promise { const apiBaseUrl = getApiBaseUrl() const normalizedPath = path.startsWith('/') ? path : `/${path}` const requestUrl = `${apiBaseUrl}${normalizedPath}` const method = init?.method ?? 'GET' - const startedAt = Date.now() - let response: Response - try { - response = await fetch(requestUrl, { - ...init, - credentials: init?.credentials ?? 'include', - }) - } catch (cause) { - const detail = cause instanceof Error ? cause.message : String(cause) - appendApiRequestLog({ - timestamp: Date.now(), - method, - url: requestUrl, - status: 0, - code: 'network_error', - message: 'Network request failed', - detail, - durationMs: Date.now() - startedAt, - }) - reportClientErrorToServer({ - method, - url: requestUrl, - status: 0, - code: 'network_error', - message: 'Network request failed', - detail, - durationMs: Date.now() - startedAt, - }) - throw new ApiError( - 'The service is temporarily unavailable. Please try again shortly.', - 0, - 'network_error', - ) - } + for (let attempt = 1; ; attempt += 1) { + const startedAt = Date.now() + let response: Response | null = null + let failure: RequestFailure | null = null - if (!response.ok) { - let bodyText = '' try { - bodyText = await response.text() - } catch { - // Ignore unreadable bodies; the status-based fallback message is used. + response = await fetch(requestUrl, { + ...init, + credentials: init?.credentials ?? 'include', + }) + } catch (cause) { + failure = { + status: 0, + code: 'network_error', + message: 'Network request failed', + detail: cause instanceof Error ? cause.message : String(cause), + } + } + + if (response && !response.ok) { + let bodyText = '' + try { + bodyText = await response.text() + } catch { + // Ignore unreadable bodies; the status-based fallback message is used. + } + const { message, code } = parseApiErrorBody(bodyText, response.status) + failure = { status: response.status, code, message, detail: bodyText || undefined } } - const { message, code } = parseApiErrorBody(bodyText, response.status) + if (failure) { + // Every attempt is logged locally — the retries are themselves a signal — + // but only the final one is reported to the backend. + appendApiRequestLog({ + timestamp: Date.now(), + method, + url: requestUrl, + status: failure.status, + code: failure.code, + message: failure.message, + detail: failure.detail, + durationMs: Date.now() - startedAt, + }) + + if (attempt < MAX_ATTEMPTS && isRetryableFailure(method, failure.status)) { + await delay(RETRY_BACKOFF_MS * attempt) + continue + } + + reportClientErrorToServer({ + method, + url: requestUrl, + status: failure.status, + code: failure.code, + message: failure.message, + detail: failure.detail, + durationMs: Date.now() - startedAt, + }) + throw new ApiError( + failure.status === 0 + ? 'The service is temporarily unavailable. Please try again shortly.' + : failure.message, + failure.status, + failure.code, + ) + } + + const okResponse = response as Response appendApiRequestLog({ timestamp: Date.now(), method, url: requestUrl, - status: response.status, - code, - message, - detail: bodyText || undefined, - durationMs: Date.now() - startedAt, - }) - reportClientErrorToServer({ - method, - url: requestUrl, - status: response.status, - code, - message, - detail: bodyText || undefined, + status: okResponse.status, + message: 'OK', durationMs: Date.now() - startedAt, }) - throw new ApiError(message, response.status, code) - } - - appendApiRequestLog({ - timestamp: Date.now(), - method, - url: requestUrl, - status: response.status, - message: 'OK', - durationMs: Date.now() - startedAt, - }) - if (response.status === 204) { - return undefined as T - } + if (okResponse.status === 204) { + return undefined as T + } - const bodyText = await response.text() - try { - return JSON.parse(bodyText) as T - } catch { - throw new ApiError( - 'Something went wrong on our side. Please try again shortly.', - response.status, - 'invalid_json', - ) + const bodyText = await okResponse.text() + try { + return JSON.parse(bodyText) as T + } catch { + throw new ApiError( + 'Something went wrong on our side. Please try again shortly.', + okResponse.status, + 'invalid_json', + ) + } } } diff --git a/frontend/src/shared/utils/reportClientError.ts b/frontend/src/shared/utils/reportClientError.ts index 74af1be..9f9aa63 100644 --- a/frontend/src/shared/utils/reportClientError.ts +++ b/frontend/src/shared/utils/reportClientError.ts @@ -11,8 +11,38 @@ export interface ClientErrorReportPayload { pagePath?: string } +/** + * A failing backend used to generate the traffic that kept it failing: 24 of the + * 43 errors captured during the August 2026 load test were these reports, each + * one provoked by a failure of the same wedged Worker. Capping them per page + * load stops a partial outage from feeding itself. + */ +const MAX_REPORTS_PER_PAGE_LOAD = 10 +let reportsSentThisPageLoad = 0 + +/** + * Statuses that are ordinary outcomes rather than defects: 401 is every + * anonymous visitor's session check, and 429 is the rate limiter working. Both + * arrive in bursts and drown out the reports worth reading. + */ +const UNREPORTED_STATUSES = new Set([401, 429]) + +/** Exported for tests; page loads reset this naturally. */ +export function resetClientErrorReportBudget(): void { + reportsSentThisPageLoad = 0 +} + +export function shouldReportClientError(status: number): boolean { + return !UNREPORTED_STATUSES.has(status) && reportsSentThisPageLoad < MAX_REPORTS_PER_PAGE_LOAD +} + /** Fire-and-forget diagnostics; the HttpOnly session cookie is sent by fetch. */ export function reportClientErrorToServer(payload: ClientErrorReportPayload): void { + if (!shouldReportClientError(payload.status)) { + return + } + reportsSentThisPageLoad += 1 + const apiBaseUrl = getApiBaseUrl() const normalizedPath = '/api/client-errors' const requestUrl = apiBaseUrl ? `${apiBaseUrl}${normalizedPath}` : normalizedPath @@ -25,7 +55,10 @@ export function reportClientErrorToServer(payload: ClientErrorReportPayload): vo }, body: JSON.stringify({ ...payload, - pagePath: payload.pagePath ?? window.location.pathname, + // This runs inside fetchJson's failure path; throwing here would replace + // the ApiError callers expect with a ReferenceError. + pagePath: + payload.pagePath ?? (typeof window === 'undefined' ? undefined : window.location.pathname), }), }).catch(() => { // Logging must never break the UI flow. diff --git a/frontend/tests/shared/apiRetry.test.ts b/frontend/tests/shared/apiRetry.test.ts new file mode 100644 index 0000000..ae19adb --- /dev/null +++ b/frontend/tests/shared/apiRetry.test.ts @@ -0,0 +1,102 @@ +import assert from 'node:assert/strict' +import test from 'node:test' +import { ApiError, fetchJson, isRetryableFailure } from '../../src/shared/utils/api.ts' +import { + reportClientErrorToServer, + resetClientErrorReportBudget, + shouldReportClientError, +} from '../../src/shared/utils/reportClientError.ts' + +interface StubbedResponse { + status: number + body: string +} + +/** + * Counts only the request under test. Diagnostics posted to /api/client-errors + * go through the same global fetch and would otherwise inflate the count. + */ +function stubFetch(responses: (StubbedResponse | Error)[]): { calls: number } { + const state = { calls: 0 } + globalThis.fetch = (async (input: RequestInfo | URL) => { + if (String(input).includes('/api/client-errors')) { + return { ok: true, status: 204, text: async () => '' } as Response + } + const next = responses[Math.min(state.calls, responses.length - 1)] + state.calls += 1 + if (next instanceof Error) { + throw next + } + return { + ok: next.status >= 200 && next.status < 300, + status: next.status, + text: async () => next.body, + } as Response + }) as typeof fetch + return state +} + +test('isRetryableFailure retries safe methods on transport and server failures', () => { + assert.equal(isRetryableFailure('GET', 0), true) + assert.equal(isRetryableFailure('GET', 500), true) + assert.equal(isRetryableFailure('GET', 503), true) + assert.equal(isRetryableFailure('head', 502), true) +}) + +test('isRetryableFailure leaves client errors and unsafe methods alone', () => { + assert.equal(isRetryableFailure('GET', 404), false) + assert.equal(isRetryableFailure('GET', 429), false) + // A POST that failed may still have been applied server-side. + assert.equal(isRetryableFailure('POST', 500), false) + assert.equal(isRetryableFailure('PUT', 0), false) +}) + +test('fetchJson recovers from a transient 500 without surfacing an error', async () => { + const state = stubFetch([ + { status: 500, body: 'Worker threw' }, + { status: 200, body: '{"ok":true}' }, + ]) + + const result = await fetchJson<{ ok: boolean }>('/api/config') + + assert.deepEqual(result, { ok: true }) + assert.equal(state.calls, 2) +}) + +test('fetchJson gives up after three attempts and throws the last failure', async () => { + const state = stubFetch([{ status: 503, body: 'error code: 1101' }]) + + await assert.rejects( + () => fetchJson('/api/config'), + (error: unknown) => error instanceof ApiError && error.status === 503, + ) + assert.equal(state.calls, 3) +}) + +test('fetchJson does not retry a failed mutation', async () => { + const state = stubFetch([{ status: 500, body: '{"error":"database_error"}' }]) + + await assert.rejects(() => fetchJson('/api/me/favorites', { method: 'PUT' })) + assert.equal(state.calls, 1) +}) + +test('shouldReportClientError skips statuses that are normal outcomes', () => { + resetClientErrorReportBudget() + + // Every anonymous visitor's session check is a 401, and a 429 is the rate + // limiter working as designed. Neither is a defect worth reporting. + assert.equal(shouldReportClientError(401), false) + assert.equal(shouldReportClientError(429), false) + assert.equal(shouldReportClientError(500), true) +}) + +test('shouldReportClientError stops once the page budget is spent', () => { + resetClientErrorReportBudget() + stubFetch([{ status: 204, body: '' }]) + + for (let index = 0; index < 10; index += 1) { + reportClientErrorToServer({ method: 'GET', url: '/api/config', status: 500, message: 'x', pagePath: '/' }) + } + + assert.equal(shouldReportClientError(500), false) +}) From 6bdbc75385eac9692d8368dc364cc3c7456d1647 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 13:40:02 +0200 Subject: [PATCH 7/8] Record the fixes and the reverted compatibility-date experiment Adds a Fixes section to the load-test report covering what changed, how each change was verified, and what remains open. Two corrections to the earlier findings. The first draft called the GIL fault "not load-dependent at all"; that was read off a run of sequential logins, but a browser was open against the same Worker throughout, so the run was never free of concurrency. Upstream describes it as needing 3-5 concurrent requests, which makes it a low-concurrency bug rather than a scale bug - below the threshold this test was built to probe. The second concerns the WebCrypto change: it adds an await to the login path, and the await boundary is exactly where the upstream race lives, so it was worth checking it does not make things worse. Twenty sequential logins on a cold isolate succeeded 3/20 with WebCrypto and 2/20 with hashlib forced - indistinguishable. That ~90% failure rate is a property of wrangler dev --remote preview isolates rather than production, and is recorded as a comparison between the two columns, not as a production figure. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 142 +++++++++++++++++++++++++++++++++++--- 1 file changed, 134 insertions(+), 8 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 68a501c..74ba6cb 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -23,11 +23,29 @@ its design live in [`load-test/README.md`](../load-test/README.md). ### Bottom line so far -The production 500s are **not a concurrency problem**. They reproduced during -plain sequential session minting, and the dominant cause is a Pyodide runtime -fault (`Attempted to use PyProxy when Python GIL not held`) that is not -load-dependent at all. Phase C would quantify how often it bites under load, but -it will not change the diagnosis or the fix. +The production 500s come from a Pyodide runtime fault +(`Attempted to use PyProxy when Python GIL not held`), tracked upstream as +[cloudflare/workerd#6624](https://github.com/cloudflare/workerd/issues/6624) and +still open. The upstream report describes it as a race in isolate re-use that +needs only 3–5 concurrent requests, which is well below the "20 users" this test +was built for — so it is a *low*-concurrency bug, not a scale bug. + +> Correction to the first draft of this report, which said the fault was "not +> load-dependent at all". That was read off a run of sequential logins, but a +> browser was open against the same Worker throughout, so the run was never +> actually free of concurrency. + +### What was fixed (2026-08-07) + +See [Fixes](#fixes) for the detail and the verification of each. + +| Fault | Status | +| --- | --- | +| Login CPU cost (Mode A) | **Fixed** — PBKDF2 moved to native WebCrypto | +| Shared-IP login lockout | **Fixed** — keyed per account, ceiling raised to 500 | +| Outages consuming login budget | **Fixed** — only real failed attempts are charged | +| `/api/client-errors` storm | **Fixed** — retries absorb transients, reports capped | +| GIL fault (Mode B) | **Upstream, unfixed** — mitigated, not resolved | ### Setup state @@ -135,9 +153,10 @@ returns `429`. If it does not, the limiter is keying on `'unknown'` for every request, which is a different and more severe problem — one global bucket for all users. -**Fix (out of scope here, separate branch):** key `auth_login` on the submitted -identifier, or on identifier+IP, so one account's failed attempts cannot lock -out everyone sharing an egress IP. +**Fixed** — `auth_login` is now keyed on the submitted identifier and charges +only genuine failed attempts. See [Fixes](#2-the-login-rate-limiter-stopped-punishing-bystanders). +The table above describes the pre-fix behaviour and is kept as the record of +what was found. --- @@ -269,6 +288,113 @@ exhausted two full windows. --- +## Fixes + +### 1. Login no longer burns half a CPU budget + +`_hash_password` ran PBKDF2-HMAC-SHA256 at 310,000 iterations through +`hashlib`, i.e. as interpreted Pyodide bytecode, for 421–538 ms of CPU per +login. That is Mode A on its own, and it holds the interpreter for long enough +to widen the window for Mode B. + +[`backend/src/password_hashing.py`](../backend/src/password_hashing.py) now +derives the same digest with `crypto.subtle.deriveBits`, which runs natively. +`hashlib` stays as a fallback so a broken fast path degrades into slow logins +rather than failed ones. + +**No hash migration is needed, and that is the load-bearing claim.** Same +algorithm, same salt, same iteration count, same 32-byte output. Verified in the +runtime rather than argued from the spec — a temporary probe route returned: + +```json +{"webcryptoUsable": true, "matchesHashlib": true} +``` + +so a hash written by `hashlib` (including every account seeded by +`seed_load_test_users.py`) verifies unchanged under WebCrypto. A full +register → login → wrong-password → login round trip was then run against the +remote preview and returned 201 / 200 / 401 / 200. + +**It also does not make Mode B worse**, which was worth checking: WebCrypto adds +an `await` to the login path, and the `await` boundary is exactly where the +upstream race lives. Twenty sequential logins one second apart, cold isolate, +each implementation forced: + +| | Succeeded | Failed | +| --- | --- | --- | +| WebCrypto | 3 / 20 | 17 | +| `hashlib` (forced) | 2 / 20 | 18 | + +Indistinguishable — the wedging is the upstream fault either way. Note that this +~90% failure rate is a property of `wrangler dev --remote` preview isolates, not +of production, where the app is broadly usable; use it to compare the two +columns, not as a production figure. + +The CPU saving itself is inferred rather than measured post-fix: wall-clock +times here are dominated by remote D1 round-trips (median 642 ms vs 694 ms), so +confirming the drop from ~450 ms of CPU needs `wrangler tail` against a deployed +build. + +### 2. The login rate limiter stopped punishing bystanders + +Three changes in +[`request_rate_limit.py`](../backend/src/services/request_rate_limit.py): + +- **Keyed on the account, not the client IP.** Twenty students behind one campus + NAT are twenty different accounts, so they no longer share a budget. This is + the shared-IP failure from Phase A, fixed. +- **Only genuine failed attempts are charged.** `enforce_failed_attempt_limit` + reads; `record_failed_attempt` writes, and only after an `AuthenticationError`. + A successful login costs nothing, and neither does a 5xx from a wedged + isolate — which is what turned an outage into a 15-minute lockout. +- **Ceiling raised to 500 per 15 minutes** (registration 5 → 50 per hour), an + explicit product call: frustrated users are the likelier harm here. + +Keying on the account would normally invite a targeted lockout — burn someone +else's budget and they cannot sign in. Counting *only failures* is what removes +that: a user with the right password never touches the counter. + +### 3. A partial outage no longer feeds itself + +24 of the 43 captured failures were `POST /api/client-errors`, the frontend's own +reporter, failing against the same wedged Worker it was reporting on. + +- [`api.ts`](../frontend/src/shared/utils/api.ts) retries `GET`/`HEAD` up to + three times on 5xx and transport errors. The GIL fault wedges one request and + serves the next normally, so this converts most of Mode B into latency the user + never sees. Mutations are not retried — a `POST` that timed out may still have + been applied. +- Only the final attempt is reported, so recovered blips generate no traffic. +- [`reportClientError.ts`](../frontend/src/shared/utils/reportClientError.ts) + caps reports at 10 per page load and drops 401/429 entirely (every anonymous + session check is a 401; a 429 is the limiter working). + +### 4. Bumping the compatibility date: tried, reverted + +The upstream issue speculates that a newer `compatibility_date` might help. It +does not — it breaks the Worker outright. At `2026-04-01`, a **cold** +`wrangler dev --remote` failed **60 out of 60** requests: + +```text +PythonWorkersInternalError: Received non-dedicated snapshot but compat flag +for dedicated snapshots is enabled + at checkSnapshotType (pyodide-internal:snapshot:560:15) + at maybeRestoreSnapshot (pyodide-internal:snapshot:586:5) +``` + +That date also flips entrypoint dispatch: local `wrangler dev` then requires +`fetch` where the deployed runtime still requires `on_fetch`, so the two +environments cannot run the same code. Both findings are recorded in +[`backend/wrangler.toml`](../backend/wrangler.toml) so the experiment is not +repeated blind. + +**Mode B therefore remains open upstream.** Nothing in this repo can fix a race +inside `preparePython`. What is fixed is everything the fault used to drag down +with it: the retry absorbs it, the reporter no longer amplifies it, and it no +longer locks anyone out of their account. + +--- + ## Notes - Runs write to the production D1. Writes are confined to the `loadtest-*` From a75d7a60872b0ca3068d34efe123a71fa21845fb Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 13:47:54 +0200 Subject: [PATCH 8/8] Correct the WebCrypto claim: workerd caps PBKDF2 at 100k iterations The previous commit claimed login CPU was moved off hashlib onto native WebCrypto. It was not. workerd rejects the call outright: NotSupportedError: Pbkdf2 failed: iteration counts above 100000 are not supported (requested 310000). PASSWORD_PBKDF2_ITERATIONS is 310,000, so crypto.subtle.deriveBits threw on every login, the fallback caught it, and hashing ran through hashlib exactly as before. The change was inert. The earlier verification proved the wrong thing. Its probe used 1,000 iterations, which is under the cap and therefore passed; it established that the FFI plumbing works, not that it works at the count actually used. The register/login round trip passed for the same reason - the fallback silently made it work. hash_password_hex now checks WEBCRYPTO_MAX_PBKDF2_ITERATIONS instead of discovering the limit by exception once per isolate, so the path is explicitly dormant. Two tests pin the constraint. Behaviour is unchanged. Two further corrections. Pyodide's hashlib is compiled C in WASM at roughly 1.5x native, not interpreted bytecode: the same work takes 313 ms as native OpenSSL, 421-538 ms in the Worker, and ~4,300 ms as a pure-Python loop. So WebCrypto was worth about a third, not an order of magnitude. And reaching it would mean dropping to <=100,000 iterations - a security decision that weakens hashing 3x and needs a per-user iteration count with rehash-on-login, against a fault that accounted for 2 of 43 observed failures. Not recommended. Co-Authored-By: Claude Opus 5 --- backend/src/password_hashing.py | 53 ++++++++----- backend/tests/test_password_hashing.py | 40 +++++++++- docs/load-test-2026-08.md | 104 ++++++++++++++++--------- 3 files changed, 139 insertions(+), 58 deletions(-) diff --git a/backend/src/password_hashing.py b/backend/src/password_hashing.py index c9f1e68..8f78462 100644 --- a/backend/src/password_hashing.py +++ b/backend/src/password_hashing.py @@ -1,19 +1,30 @@ -"""PBKDF2 password hashing, run by the runtime's native WebCrypto where available. - -`hashlib.pbkdf2_hmac` executes all 310,000 iterations as interpreted Pyodide -bytecode. Measured against production that cost 421-538 ms of CPU per login, -which is most of a Worker's budget for a single request and was enough to make -`/api/auth/login` fail outright with "Worker exceeded CPU time limit". It also -holds the interpreter for that whole stretch, which widens the window for the -Pyodide GIL race that wedges concurrent requests (cloudflare/workerd#6624). - -`crypto.subtle.deriveBits` computes the same PBKDF2-HMAC-SHA256 natively: same -salt, same iteration count, same 32-byte output. Stored hashes therefore stay -valid and no migration is needed — this is purely a change of executor. - -`hashlib` stays as the fallback so unit tests (no JS bridge) and any runtime -without WebCrypto keep working, and so a broken fast path degrades into slow -logins rather than failed ones. +"""PBKDF2 password hashing. + +Currently this always runs `hashlib`. The WebCrypto path below is dormant, and +the reason is worth recording because it is not discoverable from the docs: + + NotSupportedError: Pbkdf2 failed: iteration counts above 100000 are not + supported (requested 310000). + +Cloudflare Workers refuses `crypto.subtle.deriveBits` above 100,000 PBKDF2 +iterations. PASSWORD_PBKDF2_ITERATIONS is 310,000, so every call would throw. + +The motivation was cost. Measured against production, a login spends 421-538 ms +of CPU here, and `/api/auth/login` is the only endpoint that has failed with +"Worker exceeded CPU time limit". For scale: the same 310,000 iterations take +~313 ms as native OpenSSL and ~4.3 s as a pure-Python loop, so Pyodide's +`hashlib` is compiled C running in WASM at roughly 1.5x native — not +interpreted. Native WebCrypto would therefore have saved something in the +region of a third, not an order of magnitude. + +Using it means dropping to <=100,000 iterations, which is a security decision +(it weakens hashing against offline attack) and needs a per-user iteration +count plus rehash-on-login to migrate the stored hashes. That call has not been +made, so nothing here changes behaviour today. + +The two implementations agree byte for byte where both can run — same +algorithm, salt, iteration count and 32-byte output — which is what makes a +future switch a change of executor rather than a hash migration. """ from __future__ import annotations @@ -25,6 +36,9 @@ PASSWORD_PBKDF2_ITERATIONS = 310_000 DERIVED_KEY_BITS = 256 +# Hard limit enforced by workerd, not a tunable. +WEBCRYPTO_MAX_PBKDF2_ITERATIONS = 100_000 + # Resolved on first use. The JS bridge either exists for the lifetime of an # isolate or it does not, so probing once avoids paying an import failure on # every request under the fallback. @@ -79,15 +93,16 @@ async def hash_password_hex( global _webcrypto_usable salt_bytes = bytes.fromhex(salt_hex) - if _webcrypto_usable is not False: + # Checked rather than attempted: above the cap workerd raises on every call, + # and burning an exception per login to rediscover a fixed limit is waste. + if iterations <= WEBCRYPTO_MAX_PBKDF2_ITERATIONS and _webcrypto_usable is not False: try: digest = await _hash_password_with_webcrypto(password, salt_bytes, iterations) _webcrypto_usable = True return digest.hex() except Exception as exc: # noqa: BLE001 - any failure must degrade, not 500 _webcrypto_usable = False - # Surfaces in `wrangler tail`: logins still work, but slowly, and - # the CPU-limit failures this change exists to remove will return. + # Surfaces in `wrangler tail`. Logins keep working via hashlib. print(f'[auth] WebCrypto PBKDF2 unavailable, falling back to hashlib: {exc}') return hash_password_with_hashlib(password, salt_bytes, iterations).hex() diff --git a/backend/tests/test_password_hashing.py b/backend/tests/test_password_hashing.py index 84ff528..cdbd20a 100644 --- a/backend/tests/test_password_hashing.py +++ b/backend/tests/test_password_hashing.py @@ -16,8 +16,9 @@ class PasswordHashingTest(unittest.IsolatedAsyncioTestCase): SALT_HEX = "0123456789abcdef0123456789abcdef" - # 310,000 iterations takes seconds in CPython; the equivalence being tested - # is a property of PBKDF2, not of the iteration count. + # Under WEBCRYPTO_MAX_PBKDF2_ITERATIONS, so the WebCrypto path is reachable + # at all. The equivalence being tested is a property of PBKDF2, not of the + # iteration count. ITERATIONS = 1_000 def setUp(self) -> None: @@ -85,5 +86,40 @@ async def test_stored_hashes_stay_valid_across_the_two_implementations(self) -> self.assertEqual(recomputed, stored.hex()) +class WebCryptoIterationCapTest(unittest.IsolatedAsyncioTestCase): + """The production iteration count is above what workerd will accept.""" + + SALT_HEX = "0123456789abcdef0123456789abcdef" + + def setUp(self) -> None: + password_hashing._webcrypto_usable = None + + def tearDown(self) -> None: + password_hashing._webcrypto_usable = None + + def test_the_production_iteration_count_exceeds_the_runtime_cap(self) -> None: + # workerd: "Pbkdf2 failed: iteration counts above 100000 are not + # supported". Lowering PASSWORD_PBKDF2_ITERATIONS to reach the fast path + # weakens hashing and needs a rehash-on-login migration, so this asserts + # the constraint rather than assuming anyone remembers it. + self.assertGreater( + password_hashing.PASSWORD_PBKDF2_ITERATIONS, + password_hashing.WEBCRYPTO_MAX_PBKDF2_ITERATIONS, + ) + + async def test_webcrypto_is_not_even_attempted_above_the_cap(self) -> None: + derive = AsyncMock() + + with patch.object(password_hashing, "_hash_password_with_webcrypto", derive): + digest = await password_hashing.hash_password_hex( + "correct horse", + self.SALT_HEX, + password_hashing.WEBCRYPTO_MAX_PBKDF2_ITERATIONS + 1, + ) + + derive.assert_not_awaited() + self.assertEqual(len(digest), 64) + + if __name__ == "__main__": unittest.main() diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 74ba6cb..3dbd5af 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -41,10 +41,10 @@ See [Fixes](#fixes) for the detail and the verification of each. | Fault | Status | | --- | --- | -| Login CPU cost (Mode A) | **Fixed** — PBKDF2 moved to native WebCrypto | | Shared-IP login lockout | **Fixed** — keyed per account, ceiling raised to 500 | | Outages consuming login budget | **Fixed** — only real failed attempts are charged | | `/api/client-errors` storm | **Fixed** — retries absorb transients, reports capped | +| Login CPU cost (Mode A) | **Not fixed** — workerd caps PBKDF2 at 100k iterations | | GIL fault (Mode B) | **Upstream, unfixed** — mitigated, not resolved | ### Setup state @@ -290,50 +290,80 @@ exhausted two full windows. ## Fixes -### 1. Login no longer burns half a CPU budget +### 1. Login CPU — attempted, blocked by a runtime cap -`_hash_password` ran PBKDF2-HMAC-SHA256 at 310,000 iterations through -`hashlib`, i.e. as interpreted Pyodide bytecode, for 421–538 ms of CPU per -login. That is Mode A on its own, and it holds the interpreter for long enough -to widen the window for Mode B. +**This one is not fixed.** Recorded in full because the blocker is undocumented +and cost real time to find. -[`backend/src/password_hashing.py`](../backend/src/password_hashing.py) now -derives the same digest with `crypto.subtle.deriveBits`, which runs natively. -`hashlib` stays as a fallback so a broken fast path degrades into slow logins -rather than failed ones. +`_hash_password` runs PBKDF2-HMAC-SHA256 at 310,000 iterations through +`hashlib`, costing 421–538 ms of CPU per login. `/api/auth/login` is the only +endpoint observed failing with "Worker exceeded CPU time limit" (Mode A). -**No hash migration is needed, and that is the load-bearing claim.** Same -algorithm, same salt, same iteration count, same 32-byte output. Verified in the -runtime rather than argued from the spec — a temporary probe route returned: +Moving it to `crypto.subtle.deriveBits` does not work. workerd refuses it: -```json -{"webcryptoUsable": true, "matchesHashlib": true} +```text +NotSupportedError: Pbkdf2 failed: iteration counts above 100000 are not +supported (requested 310000). ``` -so a hash written by `hashlib` (including every account seeded by -`seed_load_test_users.py`) verifies unchanged under WebCrypto. A full -register → login → wrong-password → login round trip was then run against the -remote preview and returned 201 / 200 / 401 / 200. +The limit appears nowhere in the Workers Web Crypto documentation. It was found +by timing the two implementations inside the Worker at the *real* iteration +count — an earlier probe used 1,000 iterations, which is under the cap and so +passed, proving only that the FFI plumbing works. -**It also does not make Mode B worse**, which was worth checking: WebCrypto adds -an `await` to the login path, and the `await` boundary is exactly where the -upstream race lives. Twenty sequential logins one second apart, cold isolate, -each implementation forced: +[`password_hashing.py`](../backend/src/password_hashing.py) therefore keeps the +WebCrypto path but gates it on `WEBCRYPTO_MAX_PBKDF2_ITERATIONS`, so it is +explicitly dormant rather than throwing once per isolate. Behaviour today is +unchanged: every login still goes through `hashlib`. -| | Succeeded | Failed | -| --- | --- | --- | -| WebCrypto | 3 / 20 | 17 | -| `hashlib` (forced) | 2 / 20 | 18 | - -Indistinguishable — the wedging is the upstream fault either way. Note that this -~90% failure rate is a property of `wrangler dev --remote` preview isolates, not -of production, where the app is broadly usable; use it to compare the two -columns, not as a production figure. - -The CPU saving itself is inferred rather than measured post-fix: wall-clock -times here are dominated by remote D1 round-trips (median 642 ms vs 694 ms), so -confirming the drop from ~450 ms of CPU needs `wrangler tail` against a deployed -build. +#### How much was on the table anyway + +Less than it first looked. The same 310,000 iterations, measured: + +| Implementation | Time | +| --- | --- | +| Native OpenSSL (`hashlib`, CPython on the dev machine) | 313 ms | +| Pyodide `hashlib` in the Worker | 421–538 ms | +| Pure-Python PBKDF2 loop (extrapolated) | ~4,300 ms | + +Pyodide's `hashlib` is **compiled C running in WASM at roughly 1.5× native**, +not interpreted bytecode — the pure-Python figure is 10× further away. So native +WebCrypto was worth something like a third, not an order of magnitude. PBKDF2 is +expensive by design; no implementation makes 310,000 iterations cheap. + +#### What it would take + +Dropping to ≤100,000 iterations. That is a **security decision, not a +performance one** — it weakens the hash against offline attack by 3×, and +310,000 is already below OWASP's current PBKDF2-SHA256 guidance. It also needs a +per-user iteration count plus rehash-on-successful-login, because existing +hashes cannot be recomputed without the plaintext. + +Weighed against the benefit, this looks like a poor trade: Mode A was **2 of 43** +observed failures, against 20+ for the GIL fault. Recommend leaving the +iteration count alone unless CPU-limit failures become common. + +#### What was verified + +- The two implementations agree byte for byte below the cap + (`{"webcryptoUsable": true, "matchesHashlib": true}`), so a future switch + would be a change of executor, not a hash migration. +- The gated code does not make Mode B worse. This was worth checking, since + WebCrypto adds an `await` to the login path and the `await` boundary is where + the upstream race lives. Twenty sequential logins one second apart on a cold + isolate, each implementation forced: + + | | Succeeded | Failed | + | --- | --- | --- | + | WebCrypto | 3 / 20 | 17 | + | `hashlib` (forced) | 2 / 20 | 18 | + + Indistinguishable. That ~90% failure rate is a property of + `wrangler dev --remote` preview isolates, not of production where the app is + broadly usable — compare the two columns, do not read it as a production + figure. +- Register → login → wrong password → login against the remote preview returned + 201 / 200 / 401 / 200. ### 2. The login rate limiter stopped punishing bystanders