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/AGENTS.md b/AGENTS.md index b68c940..1537bbd 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. - **User-generated data must never be keyed on `courses.id`.** The importer reassigns course ids from 1 on every in-place re-seed, so an id-keyed row silently re-points to a different course. Key on the ALMA course number instead — `COALESCE(courses.number, courses.unit_id)`, exposed as `course_catalog.normalize_review_key()`. `course_reviews` (migration 0034) and `course_external_links` (0021) both follow this; neither belongs in the importer's `SEEDED_TABLES_DELETE_ORDER`. 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..f2b5f43 --- /dev/null +++ b/backend/scripts/seed_load_test_users.py @@ -0,0 +1,223 @@ +"""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 + 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 + 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/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. +SUPPORTED_SOURCE_STATUS = "official" +SUPPORTED_PO_VERSION = "2021" + + +def hash_password(password: str, salt_hex: str) -> str: + """Hash exactly as password_hashing.hash_password_hex 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/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..8f78462 --- /dev/null +++ b/backend/src/password_hashing.py @@ -0,0 +1,108 @@ +"""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 + +from typing import Any + +import hashlib + +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. +_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) + # 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 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/src/router.py b/backend/src/router.py index 2f8ace8..885b7d8 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, @@ -63,7 +64,9 @@ COURSE_REVIEW_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 ( @@ -344,8 +347,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 78b6a7d..e4092f4 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) @@ -40,20 +44,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, """ @@ -68,9 +88,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..cdbd20a --- /dev/null +++ b/backend/tests/test_password_hashing.py @@ -0,0 +1,125 @@ +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" + # 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: + 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()) + + +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/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/docs/load-test-2026-08.md b/docs/load-test-2026-08.md new file mode 100644 index 0000000..3dbd5af --- /dev/null +++ b/docs/load-test-2026-08.md @@ -0,0 +1,434 @@ +# 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://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` | + +## Status + +| Phase | What it establishes | Status | +| --- | --- | --- | +| 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 | **Superseded — the 500s reproduced without concurrency** | + +### Bottom line so far + +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 | +| --- | --- | +| 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 + +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. + +--- + +## 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. + +--- + +## 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. + +**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. + +--- + +## 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 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, 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 + +_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. + +### 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. + +--- + +## Fixes + +### 1. Login CPU — attempted, blocked by a runtime cap + +**This one is not fixed.** Recorded in full because the blocker is undocumented +and cost real time to find. + +`_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). + +Moving it to `crypto.subtle.deriveBits` does not work. workerd refuses it: + +```text +NotSupportedError: Pbkdf2 failed: iteration counts above 100000 are not +supported (requested 310000). +``` + +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. + +[`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`. + +#### 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 + +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-*` + 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/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) +}) diff --git a/load-test/README.md b/load-test/README.md new file mode 100644 index 0000000..c1b817e --- /dev/null +++ b/load-test/README.md @@ -0,0 +1,178 @@ +# 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.** *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. + +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.** 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 + 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 + +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..dca092b --- /dev/null +++ b/load-test/build-scenario.mjs @@ -0,0 +1,185 @@ +/** + * 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') + +// 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. + */ +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 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 firstLoad = [] + const steadyState = [] + const skipped = [] + const seenCachedPaths = new Set() + + 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 + } + + 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 { firstLoad, steadyState, 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 { 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(), + apiOrigin: DEFAULT_API_ORIGIN, + firstLoad, + steadyState, + } + + writeFileSync(OUTPUT_PATH, `${JSON.stringify(recording, null, 2)}\n`, 'utf8') + 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 { + 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..d8e8571 --- /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://studyplanner-api.ben-tischberger.workers.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..1a625f3 --- /dev/null +++ b/load-test/mint-sessions.mjs @@ -0,0 +1,265 @@ +/** + * 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 { existsSync, 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, 'sessions.json') + +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` + +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 + +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) { + 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) + }) +} + +/** + * 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', + 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) { + 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()) + 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 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() + 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)) + + // 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`) + + let loginsThisWindow = 0 + let index = 0 + while (index < pending.length) { + if (loginsThisWindow >= LOGINS_PER_BATCH) { + await waitForNextWindow('login window full') + loginsThisWindow = 0 + } + + 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( + OUTPUT_PATH, + `${JSON.stringify({ origin: args.origin, mintedAt: new Date().toISOString(), sessions }, null, 2)}\n`, + 'utf8', + ) + 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) => { + 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..831f47d --- /dev/null +++ b/load-test/recorded-session.json @@ -0,0 +1,21 @@ +{ + "source": "placeholder", + "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/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 } + ], + "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 new file mode 100644 index 0000000..6d2fe4b --- /dev/null +++ b/load-test/scenario.js @@ -0,0 +1,238 @@ +/** + * 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 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' +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://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, +// 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 || 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') +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} firstLoad=${recording.firstLoad.length} ` + + `steadyState=${recording.steadyState.length} sessions=${sessionsFile.sessions.length}`, + ) + return { firstLoadSteps: recording.firstLoad.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 [] + } +} + +// Course ids survive across a VU's iterations, the way a browser keeps the +// cached catalog after the first load. +let cachedCourseIds = [] + +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(cachedCourseIds) : 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) { + 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 +} + +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), + } +}