From f9282b003b44a0f88e45717daa748da0f3eb9bcf Mon Sep 17 00:00:00 2001 From: pixels26 Date: Fri, 21 Aug 2026 20:21:25 +0000 Subject: [PATCH] fix(privacy): prevent student-data leakage through logs and observability Closes #26. Structured logs previously carried raw student_id and attempted word values in messages and JSON fields, creating a shadow store of children's activity outside export_student_data, delete_student_data, and the retention sweep. - log_config: keyed HMAC-SHA256 pseudonymization (LOG_PSEUDONYM_KEY, environment-specific and rotatable; per-process random key fallback); never an unsalted public hash - log_config: RedactionFilter scrubbing formatted messages, plain templates, exception text, bearer/authorization headers, labeled identifier/content fields, and URL path segments in both logging modes - log_config: RFC 3339 UTC JSON timestamps and a non-identifying field allowlist that transforms legacy student_id/word extras defensively - main: request/correlation-ID middleware emitting method, route template, status, latency, and outcome; X-Request-ID response header; storage-error handler no longer echoes raw exception detail - routes/hint_generator/story_mode: logs carry only pseudonymous refs, length buckets, counts, error types, and enumerated outcomes - PRIVACY.md: data-classification policy, pseudonymization key handling, and operator obligations for external log retention/access - tests/test_log_privacy.py: capture-based regression tests asserting seeded keys/IDs/guardian IDs/words/story text never appear in either log mode, plus timestamp validity, correlation-ID propagation, and route-template redaction checks --- PRIVACY.md | 39 ++- agent/hint_generator.py | 36 ++- agent/log_config.py | 307 ++++++++++++++++++-- agent/story_mode.py | 38 ++- api/routes.py | 39 ++- main.py | 83 +++++- tests/test_agent.py | 9 +- tests/test_log_privacy.py | 578 ++++++++++++++++++++++++++++++++++++++ 8 files changed, 1075 insertions(+), 54 deletions(-) create mode 100644 tests/test_log_privacy.py diff --git a/PRIVACY.md b/PRIVACY.md index aa71fea..733f2e7 100644 --- a/PRIVACY.md +++ b/PRIVACY.md @@ -1,6 +1,6 @@ # WordBloc Privacy and Student-Data Lifecycle -**Last updated:** 2026-07-17 +**Last updated:** 2026-08-21 **Application privacy-policy version used in examples:** `2026-07-17` > **Important:** This document describes technical controls in this repository. It is not legal advice and does not, by itself, make a deployment compliant with COPPA, FERPA, state student-privacy laws, or any other law. A maintainer and qualified privacy/legal reviewer must approve the data flow, notices, contracts, and consent process before this service is used with children. @@ -40,6 +40,41 @@ The word bank is shared curriculum data and is not student-specific. Hints and s The content-safety screen in `agent/ai_safety.py` is a lightweight denylist-based heuristic intended as defense in depth, not a substitute for a managed moderation service; operators with stricter requirements should front Bedrock calls with one. +## Logging and observability + +Logs are observability data, not a student-data store. Because log sinks are typically shipped to third parties with their own retention and access rules, and because they sit outside `export_student_data`, `delete_student_data`, and the retention sweep, the service never emits managed student data in the first place (`agent/log_config.py`). Regression tests in `tests/test_log_privacy.py` fail on any seeded identifier, credential, attempted word, or generated content appearing in emitted logs, in both plain-text and JSON modes. + +### Data classification for logs + +| Class | Examples | Log treatment | +|---|---|---| +| Direct identifiers | `student_id`, `guardian_id`, account IDs | Never logged raw; replaced by keyed pseudonyms (below) | +| Learning content | Attempted words, hints, stories, prompts, free-text themes | Never logged; reduced to bounded categorical fields such as `word_length_bucket`, counts, and enumerated outcomes | +| Auth material | API keys, bearer/authorization headers | Never logged; scrubbed defensively even if a call site errs | +| Request bodies and query strings | Attempt payloads, consent metadata | Never logged | +| Provider errors | Bedrock exceptions | Logged as exception type name plus enumerated outcome; response bodies are never echoed | +| Operational metadata | Route templates, status codes, latency, request IDs, policy versions | Logged freely — all server-owned values | + +### Pseudonymous correlation + +Call sites that need to correlate records use `pseudonymize()`: a truncated HMAC-SHA256 of the identifier keyed by `LOG_PSEUDONYM_KEY`. The key is environment-specific and rotatable — rotating it permanently breaks all prior correlation links. When the variable is unset, a random per-process key is used, so values never survive restarts. Unsalted public hashes are never used, because they can be brute-forced against known ID spaces. + +Every request also receives an unguessable `X-Request-ID` (returned in the response header) that stamps each log line, so operators debug individual requests without any persistent identifier. + +### Redaction defense in depth + +`configure_logging()` installs `RedactionFilter` on the root handler so every record — including third-party loggers such as `uvicorn.access` or HTTP clients — is scrubbed across formatted messages, plain message templates, and exception text: bearer tokens, labeled credentials/identifiers/content fields (`student_id=…`, `word=…`, `api_key=…`), and identifier-bearing URL path segments are replaced with `[REDACTED]`. Structured JSON output uses an allowlist of non-identifying fields only; legacy extras carrying `student_id` or `word` are converted to `student_ref` pseudonyms and length buckets rather than dropped silently. JSON records carry UTC RFC 3339 timestamps. + +### Operator obligations for external log systems + +Application deletion cannot erase logs already exported elsewhere. Before production use, operators must: + +1. Treat every log sink (CloudWatch, ELK, Datadog, files, SIEM archives) as a processor holding potential child-activity metadata, covered by the same contracts, disclosures, and deletion/retention commitments as the primary store. +2. Set explicit retention periods on log sinks that are no longer than operationally required, and document them alongside `DATA_RETENTION_MONTHS`. +3. Restrict log access with the same rigor as the student store, since logs contain request-level activity patterns even when fully pseudonymized. +4. Protect and rotate `LOG_PSEUDONYM_KEY` like a secret; anyone holding it can correlate a child's activity across logs. +5. Remember that deleting a student's profile through the API does not propagate to independently exported or archived logs; incident-response and data-subject-request procedures must address log history separately. + ## Consent gate A new profile can be created only with all of the following `consent_metadata`: @@ -110,7 +145,7 @@ At minimum, maintainers must add or verify: - proof that the requester may access, export, or delete the specified student's record; - TLS in transit and appropriate encryption/key management at rest; - restrictive CORS through `CORS_ALLOW_ORIGINS` (never a public wildcard); -- rate limits, abuse controls, secure audit logging that avoids child data, and incident response; +- rate limits and abuse controls, incident response, and verification that the redaction pipeline in `agent/log_config.py` covers every deployed log sink (see "Logging and observability"); - secrets management and least-privilege filesystem/cloud permissions; - backup, replica, observability, and third-party processor deletion/retention controls; - a tested process to correct/amend records and handle school/parent requests; and diff --git a/agent/hint_generator.py b/agent/hint_generator.py index 7e46ea1..c7b01d8 100644 --- a/agent/hint_generator.py +++ b/agent/hint_generator.py @@ -118,24 +118,42 @@ def _bedrock_hint(word: str, theme: str) -> str | None: record_safety_outcome("hint", "generated") return hint except (BotoCoreError, ClientError) as exc: + # Provider failures are logged by type only: exception payloads can + # echo request content, and logs sit outside managed student-data + # deletion (see PRIVACY.md, "Logging and observability"). logger.warning( - "Bedrock hint unavailable for word '%s': %s", - word, exc, - extra={"source_module": __name__, "source_function": "_bedrock_hint", "word": word}, + "Bedrock hint unavailable", + extra={ + "source_module": __name__, + "source_function": "_bedrock_hint", + "feature": "hint", + "provider_outcome": "provider_unavailable", + "error_type": type(exc).__name__, + }, ) return None except UnsafeContentError as exc: record_safety_outcome("hint", "output_rejected") logger.warning( - "Bedrock hint output failed the safety/response contract for word '%s': %s", - word, exc, - extra={"source_module": __name__, "source_function": "_bedrock_hint", "word": word}, + "Bedrock hint output failed the safety/response contract", + extra={ + "source_module": __name__, + "source_function": "_bedrock_hint", + "feature": "hint", + "provider_outcome": "output_rejected", + "error_type": type(exc).__name__, + }, ) return None except Exception as exc: # noqa: BLE001 — must fall back safely on any unexpected provider error logger.error( - "Bedrock hint generation failed unexpectedly for word '%s': %s", - word, exc, - extra={"source_module": __name__, "source_function": "_bedrock_hint", "word": word}, + "Bedrock hint generation failed unexpectedly", + extra={ + "source_module": __name__, + "source_function": "_bedrock_hint", + "feature": "hint", + "provider_outcome": "provider_error", + "error_type": type(exc).__name__, + }, ) return None diff --git a/agent/log_config.py b/agent/log_config.py index 48cedf2..12c106b 100644 --- a/agent/log_config.py +++ b/agent/log_config.py @@ -2,7 +2,7 @@ Usage ----- - from agent.log_config import get_logger, configure_logging + from agent.log_config import get_logger, configure_logging, pseudonymize configure_logging() # once at startup (called from main.py) logger = get_logger(__name__) # per-module @@ -11,48 +11,316 @@ When LOG_JSON=1 is set, logs are emitted as newline-delimited JSON suitable for ingestion by log aggregators (CloudWatch, ELK, Datadog, etc.). +Logging privacy policy +---------------------- +Logs are observability data, not a student-data store, and must never become a +shadow record of children's activity. They sit outside export_student_data, +delete_student_data, and the retention sweep, so nothing identifiable may be +emitted in the first place: + +- Direct identifiers (student_id, guardian_id, account IDs) are never logged + raw. Correlation uses ``pseudonymize()``: an HMAC-SHA256 digest keyed by + LOG_PSEUDONYM_KEY. That key is environment-specific and rotatable; rotating + it makes all historical correlation values unlinkable. When the variable is + unset, a random per-process key is used so values never survive restarts. + Unsalted public hashes of identifiers are never acceptable. +- Learning content (attempted words, stories, hints, prompts, free-text + themes) is never logged. Bounded categorical fields are used instead: + ``word_length_bucket``, numeric metrics, and enumerated ``outcome`` values. +- Auth material (API keys, bearer/authorization headers) and request bodies + are never logged. +- Provider errors are logged as an exception type name plus an enumerated + outcome; provider response bodies are never echoed. +- Every handler installed by ``configure_logging()`` runs ``RedactionFilter`` + as defense in depth: message templates, %-args-formatted messages, and + exception text are scrubbed before emission, in both plain-text and JSON + modes. +- JSON records carry an RFC 3339 UTC timestamp and only allowlisted, + non-identifying extra fields. + Example JSON output (single line, pretty-printed here): { - "timestamp": "2026-07-20T12:34:56.789Z", + "timestamp": "2026-08-21T12:34:56.789Z", "level": "ERROR", "logger": "agent.hint_generator", "message": "Bedrock hint generation failed unexpectedly", - "module": "agent.hint_generator", - "function": "_bedrock_hint" + "request_id": "3f9c2b7e1a4d5e6f", + "feature": "hint", + "outcome": "provider_error", + "error_type": "ClientError" } """ +import hashlib +import hmac import json import logging import os +import re +import secrets import sys +from contextvars import ContextVar, Token +from datetime import UTC, datetime from typing import Any +_REDACTED = "[REDACTED]" +_PSEUDONYM_HEX_CHARS = 16 +_REQUEST_ID_BYTES = 8 + + # --------------------------------------------------------------------------- -# JSON formatter — emits each record as a single line of JSON. +# Pseudonymous correlation values # --------------------------------------------------------------------------- -class JsonFormatter(logging.Formatter): +_pseudonym_key_cache: bytes | None = None + + +def _pseudonym_key() -> bytes: + global _pseudonym_key_cache + if _pseudonym_key_cache is None: + configured = os.getenv("LOG_PSEUDONYM_KEY", "") + # Derive a fixed-length key from whatever the operator supplied so any + # passphrase length is safe; rotating the variable rotates every + # pseudonym derived from it. + _pseudonym_key_cache = ( + hashlib.sha256(("log-pseudonym-v1:" + configured).encode("utf-8")).digest() + if configured + else secrets.token_bytes(32) + ) + return _pseudonym_key_cache + + +def reset_pseudonym_key() -> None: + """Forget the cached key so the next call re-reads LOG_PSEUDONYM_KEY.""" + global _pseudonym_key_cache + _pseudonym_key_cache = None + + +def pseudonymize(value: str) -> str: + """Return a keyed, environment-specific pseudonymous correlation value. + + The result is a truncated HMAC-SHA256 digest prefixed with ``s_``. + Operators can correlate a student's requests across logs only while they + hold the current LOG_PSEUDONYM_KEY (or via explicit request IDs); rotating + the key permanently breaks prior links. Never call an unsalted public + hash instead: those can be brute-forced against known ID spaces. + """ + digest = hmac.new(_pseudonym_key(), value.encode("utf-8"), hashlib.sha256) + return f"s_{digest.hexdigest()[:_PSEUDONYM_HEX_CHARS]}" + + +def word_length_bucket(length: int) -> str: + """Reduce a content length to one bounded categorical bucket.""" + if length <= 3: + return "short" + if length <= 6: + return "medium" + return "long" + + +# --------------------------------------------------------------------------- +# Request/correlation context +# --------------------------------------------------------------------------- + +_request_id: ContextVar[str | None] = ContextVar("request_id", default=None) + + +def new_request_id() -> str: + return secrets.token_hex(_REQUEST_ID_BYTES) + + +def get_request_id() -> str | None: + return _request_id.get() + + +def set_request_id(request_id: str) -> Token[str | None]: + return _request_id.set(request_id) + + +def reset_request_id(token: Token[str | None]) -> None: + _request_id.reset(token) + + +class RequestContextFilter(logging.Filter): + """Stamp every handled record with the active request ID.""" + + def filter(self, record: logging.LogRecord) -> bool: + record.request_id = get_request_id() or "-" + return True + + +# --------------------------------------------------------------------------- +# Redaction — defense in depth over messages and exception text +# --------------------------------------------------------------------------- + +_BEARER_PATTERN = re.compile(r"(?i)\b(bearer)\s+[^\s'\",;)}\]]+") + +# Third-party access logs (uvicorn.access, httpx) echo raw request URLs, +# whose path segments carry student IDs or attempted words. Redact the +# segment after these route roots; values in braces are route templates +# already safe to log. +_PATH_ID_PATTERN = re.compile(r"(/(?:profile|report|neighbors)/)([^/?\s\"'{][^/?\s\"']*)") + +_SENSITIVE_FIELD_PATTERN = re.compile( + r"""(?ix) + \b( + api[_-]?key | + authorization | + proxy[-_]?authorization | + student[_-]?ids? | + guardian[_-]?id | + password | + secret | + access[-_]?token | + word + ) + (\s*[=:]\s*) + (?P + '[^']*' + | "[^"]*" + | [^\s,;)}\]]+ + ) + """ +) + + +def redact_text(text: Any) -> Any: + """Scrub credentials, identifiers, and learning-content labels from text. + + Handles ``Bearer `` authorization values, ``field=value`` / + ``field="value"`` / ``field='value'`` forms of the sensitive field names, + and identifier-bearing URL path segments. Idempotent, so it is safe to + apply at both the filter and formatter layers. + """ + if not isinstance(text, str): + return text + scrubbed = _BEARER_PATTERN.sub(r"\1 " + _REDACTED, text) + scrubbed = _SENSITIVE_FIELD_PATTERN.sub( + lambda match: f"{match.group(1)}{match.group(2)}{_REDACTED}", scrubbed + ) + scrubbed = _PATH_ID_PATTERN.sub(r"\1" + _REDACTED, scrubbed) + return scrubbed + + +class RedactionFilter(logging.Filter): + """Scrub sensitive patterns out of every record a handler emits. + + Covers %-args-formatted messages, plain message templates, and exception + text that was already rendered before the filter ran. Structured extras + are covered by the formatters' field allowlist and their defensive + transformation of legacy identifier/content fields. + """ + + def filter(self, record: logging.LogRecord) -> bool: + if record.args: + # Only the fully formatted message may be scrubbed: rewriting a + # %-template before substitution would corrupt placeholders. + try: + formatted = record.getMessage() + scrubbed = redact_text(formatted) + if scrubbed != formatted: + record.msg = scrubbed + record.args = None + except (TypeError, ValueError): + pass + elif isinstance(record.msg, str): + record.msg = redact_text(record.msg) + if record.exc_text: + record.exc_text = redact_text(record.exc_text) + return True + + +# --------------------------------------------------------------------------- +# Formatters +# --------------------------------------------------------------------------- + +class RedactingExceptionMixin(logging.Formatter): + """Ensure rendered exception text passes through redaction.""" + + def formatException(self, exc_info: Any) -> str: + return str(redact_text(super().formatException(exc_info))) + + +def _rfc3339_utc_timestamp() -> str: + return datetime.now(UTC).isoformat(timespec="milliseconds").replace("+00:00", "Z") + + +# Allowlisted, non-identifying structured fields. Anything not listed here is +# dropped from JSON output even when a caller passes it via extra={}. +_JSON_EXTRA_FIELDS = ( + "request_id", + "source_module", + "source_function", + "variant", + "feature", + "outcome", + "provider_outcome", + "error_type", + "status_code", + "latency_ms", + "http_method", + "route_template", + "student_ref", + "word_length_bucket", + "word_count", + "attempt_number", + "time_taken_seconds", +) + + +class JsonFormatter(RedactingExceptionMixin): """Format log records as newline-delimited JSON.""" def format(self, record: logging.LogRecord) -> str: obj: dict[str, Any] = { - "timestamp": self.formatTime(record, datefmt="%Y-%m-%dT%H:%M:%S.%fZ"), + "timestamp": _rfc3339_utc_timestamp(), "level": record.levelname, "logger": record.name, - "message": record.getMessage(), + "message": str(redact_text(record.getMessage())), } # Add exception data if present if record.exc_info and record.exc_info[0] is not None: obj["exception"] = self.formatException(record.exc_info) - # Add extra fields passed via extra={} - for key in ("source_module", "source_function", "student_id", "word", "variant", "feature", "outcome"): + # Legacy call sites may still attach identifying extras; convert them + # to their non-identifying equivalents instead of emitting them raw. + raw_student_id = getattr(record, "student_id", None) + if isinstance(raw_student_id, str) and raw_student_id: + obj["student_ref"] = pseudonymize(raw_student_id) + raw_word = getattr(record, "word", None) + if isinstance(raw_word, str) and raw_word: + obj["word_length_bucket"] = word_length_bucket(len(raw_word)) + # Add allowlisted extra fields passed via extra={} + for key in _JSON_EXTRA_FIELDS: + if key in obj: + continue value = getattr(record, key, None) if value is not None: obj[key] = value return json.dumps(obj, default=str, ensure_ascii=False) +class PlainTextFormatter(RedactingExceptionMixin): + """Human-oriented single-line format with a correlation ID slot.""" + + def __init__(self) -> None: + super().__init__( + fmt="%(asctime)s [%(levelname)s] [%(request_id)s] %(name)s: %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + + def format(self, record: logging.LogRecord) -> str: + if record.args: + # Scrub only after %-substitution; see RedactionFilter.filter. + try: + record.msg = redact_text(record.getMessage()) + record.args = None + except (TypeError, ValueError): + pass + elif isinstance(record.msg, str): + record.msg = redact_text(record.msg) + return super().format(record) + + # --------------------------------------------------------------------------- # Helpers # --------------------------------------------------------------------------- @@ -68,10 +336,10 @@ def _use_json() -> bool: def configure_logging() -> None: """Configure the root logger once at application startup. - Call this exactly once (e.g. from ``main.py``). After calling, - every ``logging.getLogger(__name__)`` call in any module will - produce logs consistent with the current ``LOG_LEVEL`` and - ``LOG_JSON`` settings. + Call this exactly once (e.g. from ``main.py``). After calling, every + ``logging.getLogger(__name__)`` call in any module will produce logs + consistent with the current ``LOG_LEVEL`` and ``LOG_JSON`` settings, and + every record will pass through redaction and request-context filters. """ level = _log_level() formatter: logging.Formatter @@ -79,13 +347,12 @@ def configure_logging() -> None: if _use_json(): formatter = JsonFormatter() else: - formatter = logging.Formatter( - fmt="%(asctime)s [%(levelname)s] %(name)s: %(message)s", - datefmt="%Y-%m-%d %H:%M:%S", - ) + formatter = PlainTextFormatter() handler = logging.StreamHandler(sys.stdout) handler.setFormatter(formatter) + handler.addFilter(RequestContextFilter()) + handler.addFilter(RedactionFilter()) root_logger = logging.getLogger() root_logger.setLevel(level) @@ -97,7 +364,7 @@ def configure_logging() -> None: def get_logger(name: str) -> logging.Logger: """Return a logger for the calling module. - ``configure_logging()`` must have been called once before any - ``get_logger`` call, typically in ``main.py``. + ``configure_logging()`` must have been called once before any meaningful + ``get_logger`` output, typically in ``main.py``. """ return logging.getLogger(name) diff --git a/agent/story_mode.py b/agent/story_mode.py index 39dff33..ae20599 100644 --- a/agent/story_mode.py +++ b/agent/story_mode.py @@ -92,24 +92,44 @@ def _bedrock_story(words: list) -> str | None: record_safety_outcome("story", "generated") return story except (BotoCoreError, ClientError) as exc: + # Provider failures are logged by type only; see PRIVACY.md, + # "Logging and observability". logger.warning( - "Bedrock story generation unavailable for %s word(s): %s", - word_count, exc, - extra={"source_module": __name__, "source_function": "_bedrock_story"}, + "Bedrock story generation unavailable", + extra={ + "source_module": __name__, + "source_function": "_bedrock_story", + "word_count": word_count, + "feature": "story", + "provider_outcome": "provider_unavailable", + "error_type": type(exc).__name__, + }, ) return None except UnsafeContentError as exc: record_safety_outcome("story", "output_rejected") logger.warning( - "Bedrock story output failed the safety/response contract for %s word(s): %s", - word_count, exc, - extra={"source_module": __name__, "source_function": "_bedrock_story"}, + "Bedrock story output failed the safety/response contract", + extra={ + "source_module": __name__, + "source_function": "_bedrock_story", + "word_count": word_count, + "feature": "story", + "provider_outcome": "output_rejected", + "error_type": type(exc).__name__, + }, ) return None except Exception as exc: # noqa: BLE001 — must fall back safely on any unexpected provider error logger.error( - "Bedrock story generation failed unexpectedly for %s word(s): %s", - word_count, exc, - extra={"source_module": __name__, "source_function": "_bedrock_story"}, + "Bedrock story generation failed unexpectedly", + extra={ + "source_module": __name__, + "source_function": "_bedrock_story", + "word_count": word_count, + "feature": "story", + "provider_outcome": "provider_error", + "error_type": type(exc).__name__, + }, ) return None diff --git a/api/routes.py b/api/routes.py index 6e9ad21..8debeb3 100644 --- a/api/routes.py +++ b/api/routes.py @@ -7,7 +7,7 @@ from agent.auth import Account, authorize_student, require_account, require_admin from agent.diagnostic import get_next_diagnostic_question, submit_diagnostic_answer from agent.hint_generator import get_encouragement, get_hint -from agent.log_config import get_logger +from agent.log_config import get_logger, pseudonymize, word_length_bucket from agent.privacy import delete_student_data, export_student_data from agent.profiler import ( InvalidConsentError, @@ -157,9 +157,13 @@ def create_student_profile(req: ProfileCreateRequest, account: Account = Depends consent_metadata = req.consent_metadata.model_dump(mode="json", exclude_none=True) result = create_profile(req.student_id, consent_metadata) logger.info( - "Profile created for student '%s'", - req.student_id, - extra={"source_module": __name__, "source_function": "create_student_profile", "student_id": req.student_id}, + "Profile created", + extra={ + "source_module": __name__, + "source_function": "create_student_profile", + "student_ref": pseudonymize(req.student_id), + "outcome": "created", + }, ) return result except FileExistsError as exc: @@ -182,9 +186,17 @@ def submit_attempt(req: AttemptRequest, account: Account = Depends(require_accou ) encouragement = get_encouragement(req.success, profile["consecutive_failures"]) logger.info( - "Attempt recorded: student='%s' word='%s' success=%s time=%.1fs", - req.student_id, req.word, req.success, req.time_taken_seconds, - extra={"source_module": __name__, "source_function": "submit_attempt", "student_id": req.student_id, "word": req.word}, + "Attempt recorded", + extra={ + "source_module": __name__, + "source_function": "submit_attempt", + "student_ref": pseudonymize(req.student_id), + # Learning content stays out of logs: the word is reduced to a + # bounded length bucket and the outcome to success/failure. + "word_length_bucket": word_length_bucket(len(req.word)), + "outcome": "success" if req.success else "failure", + "time_taken_seconds": req.time_taken_seconds, + }, ) return { "success": req.success, @@ -213,9 +225,16 @@ def get_word_hint(req: HintRequest): if req.use_bedrock: is_fallback = hint.startswith(("It's a", "It belongs to")) logger.info( - "Bedrock hint requested for word '%s' — fallback=%s", - req.word, is_fallback, - extra={"source_module": __name__, "source_function": "get_word_hint", "word": req.word}, + "Bedrock hint requested", + extra={ + "source_module": __name__, + "source_function": "get_word_hint", + # The attempted word is never logged; only its length bucket. + "word_length_bucket": word_length_bucket(len(req.word)), + "attempt_number": req.attempt_number, + "feature": "hint", + "provider_outcome": "fallback" if is_fallback else "generated", + }, ) return {"word": req.word, "attempt": req.attempt_number, "hint": hint} diff --git a/main.py b/main.py index 1378bb3..a1d0842 100644 --- a/main.py +++ b/main.py @@ -1,12 +1,19 @@ import asyncio import os +import time from contextlib import asynccontextmanager, suppress from fastapi import FastAPI, Request from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import JSONResponse -from agent.log_config import configure_logging, get_logger +from agent.log_config import ( + configure_logging, + get_logger, + new_request_id, + reset_request_id, + set_request_id, +) from agent.privacy import ( get_retention_sweep_interval_hours, purge_expired_profiles, @@ -95,6 +102,68 @@ async def lifespan(app: FastAPI): allow_headers=["*"], ) + +@app.middleware("http") +async def request_observability_middleware(request: Request, call_next): + """Assign a per-request correlation ID and emit bounded access metadata. + + The ID lets operators correlate a single request across log lines without + any persistent identifier; it is also returned via X-Request-ID. + """ + request_id = new_request_id() + token = set_request_id(request_id) + start = time.perf_counter() + try: + response = await call_next(request) + except Exception: + logger.exception( + "Unhandled exception on %s %s", + request.method, + getattr(request.scope.get("route"), "path_format", None) or "", + extra={ + "source_module": __name__, + "source_function": "request_observability_middleware", + "http_method": request.method, + "route_template": getattr( + request.scope.get("route"), "path_format", None + ) + or "", + "status_code": 500, + "latency_ms": round((time.perf_counter() - start) * 1000, 2), + "outcome": "server_error", + }, + ) + reset_request_id(token) + raise + latency_ms = round((time.perf_counter() - start) * 1000, 2) + response.headers["X-Request-ID"] = request_id + route = request.scope.get("route") + route_template = getattr(route, "path_format", None) or "" + logger.info( + "%s %s -> %s", + request.method, + route_template, + response.status_code, + extra={ + "source_module": __name__, + "source_function": "request_observability_middleware", + "http_method": request.method, + "route_template": route_template, + "status_code": response.status_code, + "latency_ms": latency_ms, + "outcome": ( + "server_error" + if response.status_code >= 500 + else "client_error" + if response.status_code >= 400 + else "ok" + ), + }, + ) + reset_request_id(token) + return response + + app.include_router(router) @@ -120,7 +189,17 @@ async def invalid_student_id_handler(request: Request, exc: InvalidStudentIdErro @app.exception_handler(ProfileError) async def profile_error_handler(request: Request, exc: ProfileError): - logger.error("Profile storage error: %s", exc) + # Log the exception class only: profile-error messages can embed raw + # student IDs, and log sinks live outside managed deletion. + logger.error( + "Profile storage error", + extra={ + "source_module": __name__, + "source_function": "profile_error_handler", + "error_type": type(exc).__name__, + "outcome": "storage_error", + }, + ) return JSONResponse(status_code=500, content={"detail": "Profile storage error."}) diff --git a/tests/test_agent.py b/tests/test_agent.py index deb11a3..673a279 100644 --- a/tests/test_agent.py +++ b/tests/test_agent.py @@ -934,8 +934,13 @@ def test_hint_generator_logs_non_aws_exception(self): ) call_args = mock_logger.error.call_args assert call_args is not None - # The log message should include the word - assert "cat" in str(call_args) + # The log message must identify only the failure category: + # the attempted word is learning content and stays out of + # logs (issue #26). + assert "cat" not in str(call_args), ( + "the attempted word must never appear in provider-error logs" + ) + assert "provider_error" in str(call_args) def test_hint_generator_logs_aws_exception_as_warning(self): """An AWS BotoCoreError/ClientError must be logged at WARNING level and diff --git a/tests/test_log_privacy.py b/tests/test_log_privacy.py new file mode 100644 index 0000000..f129848 --- /dev/null +++ b/tests/test_log_privacy.py @@ -0,0 +1,578 @@ +"""Regression tests preventing student-data leakage through logs (issue #26). + +These tests attach to the real logging pipeline configured by +``configure_logging()`` (by swapping the stdout handler's stream) and assert, +in both plain-text and JSON modes, that seeded identifiers, credentials, +authorization headers, attempted words, and generated content never appear in +emitted log lines across API success/failure and Bedrock failure paths. +""" + +import hashlib +import io +import json +import logging +import os +import re +import shutil +from datetime import datetime +from unittest.mock import MagicMock, patch + +import pytest +from botocore.exceptions import BotoCoreError + +# Use isolated storage roots for tests (same conventions as test_agent.py). +TEST_PROFILES_DIR = "/tmp/test_lp_student_profiles" +TEST_DIAGNOSTIC_DIR = "/tmp/test_lp_diagnostic_sessions" +TEST_REPORTS_DIR = "/tmp/test_lp_student_reports" +TEST_AUDIO_CACHE_DIR = "/tmp/test_lp_audio_cache" +TEST_ACCOUNTS_FILE = "/tmp/test_lp_accounts.json" + +PSEUDONYM_KEY_ENV = "test-log-pseudonym-key" + +CONSENT_METADATA = { + "guardian_id": "guardian_leak_probe_77", + "relationship": "parent", + "consent_given": True, + "consent_method": "verified_test_form", + "privacy_policy_version": "test-v1", + "consented_at": "2025-01-01T00:00:00+00:00", +} + +PRIMARY_KEY = "leak_probe_api_key_do_not_log" +OTHER_STUDENT_KEY = "leak_probe_other_account_key" + +STUDENT_ID = "leak_probe_student" +FOREIGN_STUDENT_ID = "leak_probe_foreign_student" +ATTEMPTED_WORD = "quizzical" +HINT_WORD = "cat" +STORY_WORDS = ["cat", "hat"] +STORY_SENTENCE_FRAGMENT = "went on a big adventure" + + +def _key_hash(raw_key): + return hashlib.sha256(raw_key.encode()).hexdigest() + + +TEST_ACCOUNTS = [ + { + "account_id": "primary", + "role": "parent", + "api_key_sha256": _key_hash(PRIMARY_KEY), + "student_ids": [STUDENT_ID], + }, + { + "account_id": "other", + "role": "parent", + "api_key_sha256": _key_hash(OTHER_STUDENT_KEY), + "student_ids": [FOREIGN_STUDENT_ID], + }, +] + +# Everything that must never surface in any emitted log line. +SENSITIVE_SEEDS = [ + PRIMARY_KEY, + OTHER_STUDENT_KEY, + CONSENT_METADATA["guardian_id"], + STUDENT_ID, + FOREIGN_STUDENT_ID, + ATTEMPTED_WORD, + HINT_WORD, + STORY_SENTENCE_FRAGMENT, +] + + +def auth(key=PRIMARY_KEY): + return {"Authorization": f"Bearer {key}"} + + +def create_consented_profile(student_id): + from agent.profiler import load_profile + + return load_profile(student_id, consent_metadata=CONSENT_METADATA) + + +@pytest.fixture(autouse=True) +def clean_profiles(): + roots = ( + TEST_PROFILES_DIR, + TEST_DIAGNOSTIC_DIR, + TEST_REPORTS_DIR, + TEST_AUDIO_CACHE_DIR, + ) + for root in roots: + os.makedirs(root, exist_ok=True) + yield + for root in roots: + shutil.rmtree(root, ignore_errors=True) + + +@pytest.fixture(autouse=True) +def patch_profiles_dir(monkeypatch): + monkeypatch.setattr("agent.profiler.PROFILES_DIR", TEST_PROFILES_DIR) + monkeypatch.setattr("agent.diagnostic.DIAGNOSTIC_DIR", TEST_DIAGNOSTIC_DIR) + monkeypatch.setattr("dashboard.report.REPORTS_DIR", TEST_REPORTS_DIR) + monkeypatch.setattr("agent.privacy.AUDIO_CACHE_DIR", TEST_AUDIO_CACHE_DIR) + + +@pytest.fixture(autouse=True) +def patch_accounts(monkeypatch): + from agent import auth as auth_module + + with open(TEST_ACCOUNTS_FILE, "w") as f: + json.dump(TEST_ACCOUNTS, f) + monkeypatch.setattr(auth_module, "ACCOUNTS_FILE", TEST_ACCOUNTS_FILE) + auth_module.reset_registry() + yield + auth_module.reset_registry() + if os.path.exists(TEST_ACCOUNTS_FILE): + os.remove(TEST_ACCOUNTS_FILE) + + +@pytest.fixture(autouse=True) +def stable_pseudonym_key(monkeypatch): + """Pin the pseudonymization key so expected correlation values are stable.""" + from agent.log_config import reset_pseudonym_key + + monkeypatch.setenv("LOG_PSEUDONYM_KEY", PSEUDONYM_KEY_ENV) + reset_pseudonym_key() + yield + reset_pseudonym_key() + + +def _capture_stream(monkeypatch, json_mode): + """Install the real logging pipeline and redirect it into a buffer.""" + from agent.log_config import configure_logging + + monkeypatch.setenv("LOG_LEVEL", "INFO") + monkeypatch.setenv("LOG_JSON", "1" if json_mode else "0") + + root = logging.getLogger() + original_handlers = root.handlers[:] + original_level = root.level + configure_logging() + + stream = io.StringIO() + root.handlers[-1].stream = stream + return stream, original_handlers, original_level + + +@pytest.fixture(params=["plain", "json"]) +def captured_logs(request, monkeypatch): + stream, handlers, level = _capture_stream( + monkeypatch, json_mode=(request.param == "json") + ) + yield stream + root = logging.getLogger() + root.handlers[:] = handlers + root.setLevel(level) + + +@pytest.fixture +def json_logs(monkeypatch): + stream, handlers, level = _capture_stream(monkeypatch, json_mode=True) + yield stream + root = logging.getLogger() + root.handlers[:] = handlers + root.setLevel(level) + + +@pytest.fixture +def client(): + from fastapi.testclient import TestClient + + from main import app + return TestClient(app) + + +def _assert_no_seeds(stream): + output = stream.getvalue() + for seed in SENSITIVE_SEEDS: + assert seed not in output, f"sensitive value {seed!r} leaked into logs:\n{output}" + + +# ── Pseudonymization ──────────────────────────────────────────────────────── + + +class TestPseudonymization: + def test_stable_for_same_input_and_key(self): + from agent.log_config import pseudonymize + + first = pseudonymize(STUDENT_ID) + second = pseudonymize(STUDENT_ID) + assert first == second + assert first.startswith("s_") + assert len(first) == 18 # "s_" + 16 hex characters + assert re.fullmatch(r"s_[0-9a-f]{16}", first) + + def test_differs_per_identifier(self): + from agent.log_config import pseudonymize + + assert pseudonymize(STUDENT_ID) != pseudonymize(FOREIGN_STUDENT_ID) + + def test_rotation_changes_all_values(self, monkeypatch): + from agent.log_config import pseudonymize, reset_pseudonym_key + + before = pseudonymize(STUDENT_ID) + monkeypatch.setenv("LOG_PSEUDONYM_KEY", f"{PSEUDONYM_KEY_ENV}-rotated") + reset_pseudonym_key() + after = pseudonymize(STUDENT_ID) + assert before != after + + def test_unset_key_is_process_random(self, monkeypatch): + from agent.log_config import pseudonymize, reset_pseudonym_key + + monkeypatch.delenv("LOG_PSEUDONYM_KEY", raising=False) + reset_pseudonym_key() + first = pseudonymize(STUDENT_ID) + reset_pseudonym_key() + second = pseudonymize(STUDENT_ID) + assert first != second + + def test_never_an_unsalted_public_hash(self): + from agent.log_config import pseudonymize + + unsalted = hashlib.sha256(STUDENT_ID.encode()).hexdigest() + value = pseudonymize(STUDENT_ID)[2:] + assert value != unsalted + assert unsalted[: len(value)] != value + assert STUDENT_ID not in value + + def test_environment_separation(self, monkeypatch): + from agent.log_config import pseudonymize, reset_pseudonym_key + + production = pseudonymize(STUDENT_ID) + monkeypatch.setenv("LOG_PSEUDONYM_KEY", "staging-key") + reset_pseudonym_key() + staging = pseudonymize(STUDENT_ID) + assert production != staging + + +# ── Redaction filter ──────────────────────────────────────────────────────── + + +class TestRedactionFilter: + @pytest.mark.parametrize("json_mode", [False, True], ids=["plain", "json"]) + def test_labeled_fields_and_bearer_tokens_are_scrubbed( + self, monkeypatch, json_mode + ): + stream, handlers, level = _capture_stream(monkeypatch, json_mode) + try: + logging.getLogger("probe").info( + "debug dump: authorization=%s student_id=%s word=%s api_key=%s", + auth()["Authorization"], + STUDENT_ID, + HINT_WORD, + PRIMARY_KEY, + ) + output = stream.getvalue() + for seed in ( + PRIMARY_KEY, + STUDENT_ID, + HINT_WORD, + auth()["Authorization"].split()[1], + ): + assert seed not in output + assert "[REDACTED]" in output + finally: + root = logging.getLogger() + root.handlers[:] = handlers + root.setLevel(level) + + @pytest.mark.parametrize("json_mode", [False, True], ids=["plain", "json"]) + def test_exception_text_is_redacted(self, monkeypatch, json_mode): + stream, handlers, level = _capture_stream(monkeypatch, json_mode) + try: + try: + raise ValueError( + f"lookup failed: student_id={STUDENT_ID} " + f"api_key={PRIMARY_KEY} word={ATTEMPTED_WORD}" + ) + except ValueError: + logging.getLogger("probe").exception("Operation failed") + output = stream.getvalue() + for seed in (STUDENT_ID, PRIMARY_KEY, ATTEMPTED_WORD): + assert seed not in output + assert "[REDACTED]" in output + finally: + root = logging.getLogger() + root.handlers[:] = handlers + root.setLevel(level) + + def test_legacy_identifier_extras_are_transformed_not_emitted(self, json_logs): + from agent.log_config import pseudonymize + + logging.getLogger("probe").warning( + "legacy call site", + extra={"student_id": STUDENT_ID, "word": ATTEMPTED_WORD}, + ) + payload = json.loads(json_logs.getvalue().strip()) + assert payload["student_ref"] == pseudonymize(STUDENT_ID) + assert payload["word_length_bucket"] == "long" + serialized = json.dumps(payload) + for seed in (STUDENT_ID, ATTEMPTED_WORD): + assert seed not in serialized + + +# ── JSON timestamps ───────────────────────────────────────────────────────── + + +class TestJsonTimestamps: + def test_timestamps_are_utc_rfc3339_with_subsecond_precision(self, json_logs): + logging.getLogger("probe").info("timestamp probe") + payload = json.loads(json_logs.getvalue().strip().splitlines()[-1]) + parsed = datetime.fromisoformat(payload["timestamp"]) + assert parsed.tzinfo is not None + assert parsed.utcoffset().total_seconds() == 0 + assert "." in payload["timestamp"] + assert payload["timestamp"].endswith("Z") + + +# ── End-to-end leakage probes ─────────────────────────────────────────────── + + +class TestApiPathsDoNotLeakStudentData: + """Exercise tested API/Bedrock/privacy paths; fail on any seed leakage.""" + + def test_success_paths(self, client, captured_logs): + created = client.post( + "/api/v1/profile", + json={"student_id": STUDENT_ID, "consent_metadata": CONSENT_METADATA}, + headers=auth(), + ) + assert created.status_code == 201 + + attempt_ok = client.post( + "/api/v1/attempt", + json={ + "student_id": STUDENT_ID, + "word": ATTEMPTED_WORD, + "success": True, + "time_taken_seconds": 7.5, + "phonics_tags": ["CVC"], + "theme": "animals", + "difficulty": 2, + }, + headers=auth(), + ) + assert attempt_ok.status_code == 200 + + attempt_fail = client.post( + "/api/v1/attempt", + json={ + "student_id": STUDENT_ID, + "word": ATTEMPTED_WORD, + "success": False, + "time_taken_seconds": 12.0, + "phonics_tags": ["CVC"], + "theme": "animals", + "difficulty": 3, + }, + headers=auth(), + ) + assert attempt_fail.status_code == 200 + + hint = client.post( + "/api/v1/hint", + json={ + "word": HINT_WORD, + "theme": "animals", + "attempt_number": 1, + "use_bedrock": False, + }, + headers=auth(), + ) + assert hint.status_code == 200 + + story = client.post( + "/api/v1/story", + json={ + "student_id": STUDENT_ID, + "words": STORY_WORDS, + "use_bedrock": False, + }, + headers=auth(), + ) + assert story.status_code == 200 + # Generated content reaches the authorized caller, never the logs. + assert STORY_SENTENCE_FRAGMENT in story.json()["story"] + + report = client.get(f"/api/v1/report/{STUDENT_ID}", headers=auth()) + assert report.status_code == 200 + + exported = client.get( + f"/api/v1/profile/{STUDENT_ID}/export", headers=auth() + ) + assert exported.status_code == 200 + + deleted = client.delete(f"/api/v1/profile/{STUDENT_ID}", headers=auth()) + assert deleted.status_code == 200 + + _assert_no_seeds(captured_logs) + + def test_failure_paths(self, client, captured_logs): + unauthorized = client.post( + "/api/v1/attempt", + json={ + "student_id": STUDENT_ID, + "word": ATTEMPTED_WORD, + "success": True, + "time_taken_seconds": 1.0, + "phonics_tags": ["CVC"], + "theme": "animals", + "difficulty": 1, + }, + headers=auth(key="totally_wrong_key"), + ) + assert unauthorized.status_code == 401 + + forbidden = client.post( + "/api/v1/attempt", + json={ + "student_id": FOREIGN_STUDENT_ID, + "word": ATTEMPTED_WORD, + "success": True, + "time_taken_seconds": 1.0, + "phonics_tags": ["CVC"], + "theme": "animals", + "difficulty": 1, + }, + headers=auth(), # valid key, foreign student + ) + assert forbidden.status_code == 403 + + missing = client.get(f"/api/v1/profile/{STUDENT_ID}", headers=auth()) + assert missing.status_code == 404 + + conflict = client.post( + "/api/v1/profile", + json={"student_id": STUDENT_ID, "consent_metadata": CONSENT_METADATA}, + headers=auth(), + ) + assert conflict.status_code == 201 + duplicate = client.post( + "/api/v1/profile", + json={"student_id": STUDENT_ID, "consent_metadata": CONSENT_METADATA}, + headers=auth(), + ) + assert duplicate.status_code == 409 + + _assert_no_seeds(captured_logs) + + def test_bedrock_provider_failure_path(self, client, captured_logs): + create_consented_profile(STUDENT_ID) + with patch("agent.hint_generator.boto3.client", side_effect=BotoCoreError()): + r = client.post( + "/api/v1/hint", + json={ + "word": HINT_WORD, + "theme": "animals", + "attempt_number": 1, + "use_bedrock": True, + }, + headers=auth(), + ) + assert r.status_code == 200 + assert r.json()["hint"] # deterministic fallback served + output = captured_logs.getvalue() + assert "Bedrock hint unavailable" in output + _assert_no_seeds(captured_logs) + + def test_bedrock_unsafe_output_failure_path(self, client, captured_logs): + create_consented_profile(STUDENT_ID) + # Outer Bedrock envelope is valid JSON; the model's inner text is not, + # exercising the structured-contract rejection path. + malformed = MagicMock() + malformed["body"].read.return_value = json.dumps( + {"content": [{"text": "not-json"}]} + ).encode() + with patch("agent.story_mode.boto3.client") as mock_client: + mock_client.return_value.invoke_model.return_value = malformed + r = client.post( + "/api/v1/story", + json={ + "student_id": STUDENT_ID, + "words": STORY_WORDS, + "use_bedrock": True, + }, + headers=auth(), + ) + assert r.status_code == 200 + assert STORY_SENTENCE_FRAGMENT in r.json()["story"] + assert "safety/response contract" in captured_logs.getvalue() + _assert_no_seeds(captured_logs) + + +class TestObservabilityMetadata: + def test_request_id_correlates_response_header_and_logs( + self, client, captured_logs + ): + create_consented_profile(STUDENT_ID) + r = client.get(f"/api/v1/profile/{STUDENT_ID}", headers=auth()) + assert r.status_code == 200 + request_id = r.headers.get("X-Request-ID") + assert request_id + assert re.fullmatch(r"[0-9a-f]{16}", request_id) + assert request_id in captured_logs.getvalue() + _assert_no_seeds(captured_logs) + + def test_route_templates_replace_raw_paths_in_logs( + self, client, captured_logs + ): + create_consented_profile(STUDENT_ID) + r = client.get(f"/api/v1/profile/{STUDENT_ID}/export", headers=auth()) + assert r.status_code == 200 + assert "/api/v1/profile/{student_id}/export" in captured_logs.getvalue() + _assert_no_seeds(captured_logs) + + def test_json_access_line_carries_bounded_fields(self, client, json_logs): + r = client.post( + "/api/v1/hint", + json={ + "word": HINT_WORD, + "theme": "animals", + "attempt_number": 1, + "use_bedrock": False, + }, + headers=auth(), + ) + assert r.status_code == 200 + access_entries = [ + json.loads(line) + for line in json_logs.getvalue().strip().splitlines() + if "route_template" in line + ] + assert access_entries, "expected at least one access-log line" + entry = access_entries[-1] + assert entry["http_method"] == "POST" + assert entry["route_template"] == "/api/v1/hint" + assert entry["status_code"] == 200 + assert isinstance(entry["latency_ms"], float) + assert entry["outcome"] == "ok" + assert entry["request_id"] + _assert_no_seeds(json_logs) + + def test_hint_provider_failure_logs_only_type_and_outcome(self, client, json_logs): + create_consented_profile(STUDENT_ID) + with patch("agent.hint_generator.boto3.client", side_effect=BotoCoreError()): + r = client.post( + "/api/v1/hint", + json={ + "word": HINT_WORD, + "theme": "animals", + "attempt_number": 1, + "use_bedrock": True, + }, + headers=auth(), + ) + assert r.status_code == 200 + entries = [ + json.loads(line) + for line in json_logs.getvalue().strip().splitlines() + if '"agent.hint_generator"' in line and "provider_outcome" in line + ] + assert entries, "expected a provider-outcome log line" + entry = entries[-1] + assert entry["provider_outcome"] == "provider_unavailable" + assert entry["error_type"] == "BotoCoreError" + assert entry["feature"] == "hint" + _assert_no_seeds(json_logs)