diff --git a/backend/app/downloads/backfill.py b/backend/app/downloads/backfill.py index 76d8258c..b4de7c6a 100644 --- a/backend/app/downloads/backfill.py +++ b/backend/app/downloads/backfill.py @@ -12,6 +12,7 @@ Run once per environment: """ import logging +from urllib.parse import urlsplit import yt_dlp from sqlalchemy import select @@ -26,7 +27,7 @@ from app.models import MediaAsset log = logging.getLogger("siftlode.backfill") -def _extract_meta(url: str, adapter: adapters.SourceAdapter) -> dict | None: +def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: """Metadata-only yt-dlp extraction, using the source adapter's client sets + options (YouTube needs the POT/player-client strategy even just to extract).""" for clients in adapter.client_sets(): @@ -40,7 +41,18 @@ def _extract_meta(url: str, adapter: adapters.SourceAdapter) -> dict | None: if info: return info except Exception as exc: # noqa: BLE001 — best-effort backfill, keep going - log.info("meta extract failed for %s (%s): %s", url, clients, str(exc)[:100]) + # The asset id, not the URL. A source URL is a row of this user's download + # history, and `redact_text` only takes credential params out of it — the rest + # of it goes in whole. The id names the same asset to anyone holding the + # database and nothing at all to anyone who is not; the host is kept because it + # is what decides which client set was tried. + log.info( + "meta extract failed for asset %s on %s (%s): %s", + asset_id, + urlsplit(url).hostname or "?", # log-pii-ok: the host, never the path or query + clients, + str(exc)[:100], + ) return None @@ -60,7 +72,7 @@ def run() -> dict: adapter = adapters.resolve_adapter(a.source_kind, a.source_ref) if a.uploader_url is None and adapter.wants_metadata_backfill(): url = a.source_webpage_url or service.source_url(a.source_kind, a.source_ref) - info = _extract_meta(url, adapter) + info = _extract_meta(url, adapter, a.id) uu = adapter.uploader_url(info) if info else None if uu: a.uploader_url = uu diff --git a/backend/app/email.py b/backend/app/email.py index 1c08e0e4..860a89d5 100644 --- a/backend/app/email.py +++ b/backend/app/email.py @@ -155,7 +155,15 @@ def _send(to: list[str], subject: str, body: str, reply_to: str | None = None) - return False c = _smtp() if not (c["host"] and c["user"] and c["password"]): - log.info("SMTP not configured; skipping email %r to %s", subject, recipients) + # The count, not the addresses: `redact_text` rewrites every one of them to `[email]` + # before either sink sees the line, so the list only ever printed as noise. The subject + # stays — the templates are static, and the one that interpolates (`admin_new_request`) + # interpolates an address, which the same redactor covers. + log.info( + "SMTP not configured; skipping email %r to %d recipient(s)", + subject, + len(recipients), # log-pii-ok: how many, not who + ) _alert_admins("not_configured", subject, recipients) return False msg = EmailMessage() @@ -176,10 +184,12 @@ def _send(to: list[str], subject: str, body: str, reply_to: str | None = None) - s.starttls(context=ssl.create_default_context()) s.login(c["user"], c["password"]) s.send_message(msg) - log.info("Sent email %r to %s", subject, recipients) + # log-pii-ok: how many, not who + log.info("Sent email %r to %d recipient(s)", subject, len(recipients)) return True except Exception: - log.exception("SMTP send failed (%r to %s)", subject, recipients) + # log-pii-ok: how many, not who + log.exception("SMTP send failed (%r to %d recipient(s))", subject, len(recipients)) _alert_admins("send_failed", subject, recipients) return False diff --git a/backend/app/main.py b/backend/app/main.py index a4c1f44a..27cd1176 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -83,7 +83,7 @@ async def lifespan(app: FastAPI): log.warning( "FIRST-RUN SETUP REQUIRED — this instance isn't configured yet.\n" " Open the install wizard (internal access only):\n %s", - url, + url, # log-pii-ok: this instance's OWN setup URL, and `?token=` is redacted ) # No HLS session survives a restart (they live in this process), so anything still on disk is # a crashed run's segments — sweep them or they accumulate forever. FIRE AND FORGET, not diff --git a/backend/app/routes/auth.py b/backend/app/routes/auth.py index 97bae871..df9f8f30 100644 --- a/backend/app/routes/auth.py +++ b/backend/app/routes/auth.py @@ -17,6 +17,7 @@ from sqlalchemy.exc import IntegrityError from sqlalchemy.orm import Session from app import email as email_mod +from app import logs from app import mailtext from app import sysconfig from app.auth import ( @@ -386,7 +387,15 @@ async def callback( return _complete_link(request, db, link_uid, link_explicit, sub, userinfo, token) if not is_allowed(db, email): - log.warning("Login denied (not approved): %s", email or "") + # No uid to name — having no account here is the branch. And the address is left out on + # purpose: `redact_text` turns it into `[email]` before either sink sees it, so a line + # whose only variable is always `[email]` says nothing. WHO asked is in the pending + # invite recorded just below, which is where an admin looks anyway. + log.warning( + "Google sign-in denied: address not approved", + # log-pii-ok: whether an address came back, not what it was + extra=logs.event("auth.login.denied", reason="not_approved", has_email=bool(email)), + ) # A denied Google login doubles as an access request: record it for the admin and # land the user on a friendly "request received" screen instead of a raw 403. if email: @@ -419,15 +428,20 @@ async def callback( if existing.google_sub is not None and existing.google_sub != sub: # A different Google identity is already bound to this email — refuse rather than # hijack it. (Near-impossible with real Google accounts: email↔sub is stable.) - log.warning("Google login email collision (different sub): %s", email) + log.warning( + "Google sign-in refused: a different Google identity holds this address", + extra=logs.event("auth.login.denied", reason="sub_collision", uid=existing.id), + ) return RedirectResponse(url=_access_notice_url("denied")) if not userinfo.get("email_verified", False): # Adopting (and activating) a pre-existing password account requires Google to # actually attest the address — otherwise an unverified Google email that merely # collides with a pending registration could seize that account. Defense-in-depth. log.warning( - "Google login: unverified email, refusing to adopt account: %s", - email, + "Google sign-in refused: unverified address, not adopting the account", + extra=logs.event( + "auth.login.denied", reason="email_unverified", uid=existing.id + ), ) return RedirectResponse(url=_access_notice_url("denied")) user = existing @@ -445,7 +459,10 @@ async def callback( # A suspended account can't sign in by any method. Block before establishing the session and # tell the (verified) owner why — a successful Google auth proves they control this account. if user.is_suspended: - log.info("Suspended account blocked at Google login: %s", email) + log.info( + "Google sign-in blocked: the account is suspended", + extra=logs.event("auth.login.denied", reason="suspended", uid=user.id), + ) _notify_suspended(background, user) return RedirectResponse(url="/?login=suspended") # Record what Google actually answers with, beside the address the user registered with. The two @@ -481,7 +498,10 @@ async def callback( _store_token(db, user, token) _establish_session(request, user) db.commit() - log.info("Login: %s (id=%s, role=%s)", email, user.id, user.role) + log.info( + "signed in", + extra=logs.event("auth.login.ok", method="google", uid=user.id, role=user.role), + ) return RedirectResponse(url="/") @@ -661,7 +681,8 @@ def demo_login(body: EmailIn, request: Request, db: Session = Depends(get_db)) - request.session.clear() request.session["user_id"] = demo.id _remember_epoch(request, demo) - log.info("Demo login (key=%s, demo_id=%s)", email, demo.id) + # The demo key IS an address, so it is not in the line — see the denied branch above. + log.info("signed in", extra=logs.event("auth.login.ok", method="demo", uid=demo.id)) return {"authenticated": True} return {"authenticated": False} @@ -1049,7 +1070,10 @@ def password_login( raise _login_refused(403, "pending_approval", user) _establish_session(request, user) db.commit() - log.info("Password login: %s (id=%s, role=%s)", email, user.id, user.role) + log.info( + "signed in", + extra=logs.event("auth.login.ok", method="password", uid=user.id, role=user.role), + ) return {"ok": True} diff --git a/backend/app/routes/channels.py b/backend/app/routes/channels.py index 4c868976..9d5ff801 100644 --- a/backend/app/routes/channels.py +++ b/backend/app/routes/channels.py @@ -559,8 +559,16 @@ def subscribe( # subscription resync fills in the resource id. Any other YouTube error is a real # problem — surface it with a clear message (422, not a 502 that the client would # mistake for a transient "connection lost"). + # On the reason code, not on the prose: `_upstream_failure` builds the message from + # the code now, and a message YouTube rewords would silently turn "already following" + # back into a 422 the user cannot act on. The substring check stays beside it for a + # body that carried no reason at all (`` / ``). msg = str(exc).lower() - if "already exists" in msg or "duplicate" in msg: + if ( + exc.reason == "subscriptionDuplicate" + or "already exists" in msg + or "duplicate" in msg + ): yt_sub_id = "" else: raise HTTPException( diff --git a/backend/app/routes/search.py b/backend/app/routes/search.py index 91ecad5d..8d56655e 100644 --- a/backend/app/routes/search.py +++ b/backend/app/routes/search.py @@ -23,7 +23,7 @@ from sqlalchemy import and_, delete, func, or_, select, update from sqlalchemy.dialects.postgresql import insert as pg_insert from sqlalchemy.orm import Session, aliased -from app import quota, sysconfig +from app import logs, quota, sysconfig from app.auth import require_human from app.db import get_db from app.models import ( @@ -291,7 +291,28 @@ def search_youtube( collected.extend(_ingest_candidates(db, yt, user, candidates)) except Exception as exc: # noqa: BLE001 — any ingest failure, not just YouTubeError db.rollback() - log.exception("live search ingest failed for %r", term) + # The term is NOT in this line. A search string is exactly what the privacy + # policy keeps out of the log unless the user turned Teljes/TRACE on for + # themselves, and `redact_text` does not cover it — it scrubs addresses and + # credential params, not what someone typed into the search box. What the + # ERROR line carries instead is the shape of the failure, which is what tells + # an ingest bug from an upstream one; the term follows at TRACE, where the + # consent that allows it is the only thing that emits the record at all. + log.exception( + "live search ingest failed", + extra=logs.event( + "search.live.ingest_failed", + source=source, + candidates=len(candidates), + collected=len(collected), + ), + ) + log.log( + logs.TRACE, + "the term the ingest failed on", + # log-pii-ok: TRACE is the consented level, and this is what it is for + extra=logs.event("search.live.term", term=term), + ) if collected: break # keep what earlier pages already gathered raise HTTPException( diff --git a/backend/app/youtube/client.py b/backend/app/youtube/client.py index 2797c7e8..7ba4dfb6 100644 --- a/backend/app/youtube/client.py +++ b/backend/app/youtube/client.py @@ -12,7 +12,7 @@ from datetime import datetime, timedelta, timezone import httpx -from app import quota, sysconfig +from app import logs, quota, sysconfig from app.models import User from app.security import decrypt, decrypt_optional, encrypt @@ -23,7 +23,58 @@ API_BASE = "https://www.googleapis.com/youtube/v3" class YouTubeError(Exception): - pass + """An upstream YouTube Data API failure. + + `reason` is the API's own error reason code (`quotaExceeded`, `subscriptionDuplicate`, + `videoNotFound`, …) when the body carried one. Branch on THAT, never on the message: the + message is prose, it changes under us, and it is deliberately the poorer of the two here.""" + + def __init__(self, message: str, *, reason: str = ""): + super().__init__(message) + self.reason = reason + + +def _error_reason(resp: httpx.Response) -> str: + """The `reason` YouTube puts on an API error. That is the whole diagnostic value of an error + body; the `message` beside it is prose, and upstream prose can quote the request back — a + search term, a playlist title.""" + try: + errors = resp.json().get("error", {}).get("errors") or [] + reasons = ",".join(e.get("reason", "") for e in errors if e.get("reason")) + except Exception: # noqa: BLE001 — any non-JSON body (an HTML error page from a proxy) + return "" + return reasons or "" + + +def _upstream_failure(method: str, path: str, resp: httpx.Response) -> YouTubeError: + """Report one upstream failure and build the error to raise. Every failing YouTube call goes + through here, so what may appear in a log line cannot drift apart between the read, the write + and the delete path — and the error a caller raises carries the reason code rather than the + body, because callers put it in a log line (`routes/channels.py`) and in a 422 answered to the + user. The body itself is TRACE-only: it is the request quoted back, which the privacy policy + keeps out of the log unless the user turned Teljes on for themselves.""" + reason = _error_reason(resp) + log.warning( + "YouTube %s %s -> %s (%s)", + method, + path, + resp.status_code, + reason, + extra=logs.event( + "youtube.api.error", + method=method, + path=path, + status=resp.status_code, + reason=reason, + ), + ) + log.log( + logs.TRACE, + "the upstream body behind it", + # log-pii-ok: TRACE is the consented level, and this is what it is for + extra=logs.event("youtube.api.body", body=resp.text[:500]), + ) + return YouTubeError(f"{method} {path} -> {resp.status_code}: {reason}", reason=reason) def _chunks(items: list, size: int) -> Iterator[list]: @@ -62,8 +113,8 @@ class YouTubeClient: YouTubeError — degrade gracefully, log, and move on — so wrapping here keeps a transient network fault (e.g. the fixed-IP egress proxy being unreachable) from escaping as a raw httpx error and turning into an uncaught 500. HTTP status errors - are NOT touched here (we don't use raise_for_status): callers inspect resp.status_code - themselves and raise their own YouTubeError with the response body.""" + are NOT touched here (we don't use raise_for_status): each call site inspects + resp.status_code itself and hands the response to `_upstream_failure`.""" try: return self._http.request(method, url, **kwargs) except httpx.HTTPError as exc: @@ -121,8 +172,7 @@ class YouTubeClient: resp = self._send("GET", f"{API_BASE}/{path}", params=p, headers=headers) quota.record_usage(cost) if resp.status_code != 200: - log.warning("YouTube API %s -> %s: %s", path, resp.status_code, resp.text[:200]) - raise YouTubeError(f"GET {path} -> {resp.status_code}: {resp.text[:300]}") + raise _upstream_failure("GET", path, resp) return resp.json() # --- endpoints --- @@ -247,12 +297,7 @@ class YouTubeClient: ) quota.record_usage(50) if resp.status_code not in (200, 204): - log.warning( - "YouTube subscriptions.delete -> %s: %s", - resp.status_code, - resp.text[:200], - ) - raise YouTubeError(f"DELETE subscriptions -> {resp.status_code}: {resp.text[:300]}") + raise _upstream_failure("DELETE", "subscriptions", resp) def insert_subscription(self, channel_id: str) -> str: """Subscribe to a channel on YouTube. Requires the write scope and the user's @@ -282,8 +327,7 @@ class YouTubeClient: resp = self._send(method, f"{API_BASE}/{path}", params=params, json=json, headers=headers) quota.record_usage(50) if resp.status_code not in (200, 204): - log.warning("YouTube %s %s -> %s: %s", method, path, resp.status_code, resp.text[:200]) - raise YouTubeError(f"{method} {path} -> {resp.status_code}: {resp.text[:300]}") + raise _upstream_failure(method, path, resp) return resp.json() if resp.content else {} def get_playlist_snippet(self, playlist_id: str) -> dict | None: diff --git a/backend/tests/test_log_pii.py b/backend/tests/test_log_pii.py new file mode 100644 index 00000000..aa7a10e2 --- /dev/null +++ b/backend/tests/test_log_pii.py @@ -0,0 +1,213 @@ +"""E22.5 S1 — what a log line may NOT carry. + +`logs.redact_text` is a safety net over addresses and credential params, and it was doing the whole +job: every one of these call sites was putting user content into a line and relying on the net to +catch it. Two things were wrong with that. What the net does NOT cover went in whole — a search +term, a source URL, an upstream body that quotes the request back — and what it DOES cover came out +as `[email]`, so the line's one variable was a constant and the line said nothing. + +The cases below pin the call sites. The last one pins the family: no future log call may pass the +same kind of value without saying, on the line, why it is safe. +""" + +import ast +import json +import logging +import pathlib + +import httpx +import pytest + +from app import logs +from app.youtube.client import YouTubeError, _upstream_failure + +TERM = "the exact thing they typed" + + +class _Sink(logging.Handler): + """The stdout handler's own filter and formatter, so a case sees the bytes a deployment writes + — not the record before redaction ran.""" + + def __init__(self): + super().__init__(level=logging.NOTSET) + self.lines: list[str] = [] + self.setFormatter(logs.JsonFormatter()) + self.addFilter(logs.ContextFilter()) + + def emit(self, record): + self.lines.append(self.format(record)) + + def objects(self) -> list[dict]: + return [json.loads(line) for line in self.lines] + + def at(self, level: str) -> list[dict]: + return [o for o in self.objects() if o["level"] == level] + + +@pytest.fixture +def sink(): + logger = logging.getLogger("siftlode") + handler = _Sink() + previous = logger.level + logger.addHandler(handler) + logger.setLevel(logs.TRACE) + try: + yield handler + finally: + logger.removeHandler(handler) + logger.setLevel(previous) + + +def _youtube_403(term: str) -> httpx.Response: + """A real-shaped Data API error. `message` is prose, and prose from an upstream quotes the + request back — which is how a search term ends up in our log through someone else's words.""" + return httpx.Response( + 403, + json={ + "error": { + "code": 403, + "message": f"The request for '{term}' cannot be completed: quota exceeded.", + "errors": [{"reason": "quotaExceeded", "domain": "youtube.quota"}], + } + }, + request=httpx.Request("GET", "https://www.googleapis.com/youtube/v3/search"), + ) + + +def test_an_upstream_failure_logs_the_reason_code_and_not_the_body(sink): + err = _upstream_failure("GET", "search", _youtube_403(TERM)) + + (line,) = sink.at("WARNING") + assert line["attrs"]["reason"] == "quotaExceeded" + assert line["attrs"]["status"] == 403 + assert TERM not in json.dumps(line) + # The error is raised to callers that put it in a log line of their own (routes/channels.py) + # and in a 422 answered to the user, so the body must not travel in it either. + assert TERM not in str(err) + assert err.reason == "quotaExceeded" + + +def test_the_body_is_kept_for_the_one_user_who_consented_to_it(sink): + _upstream_failure("GET", "search", _youtube_403(TERM)) + + # TRACE is emitted only while the user has turned Teljes on for their own session, which is + # exactly the consent the privacy policy describes. The diagnostic is not lost, it is gated. + (trace,) = sink.at("TRACE") + assert TERM in trace["attrs"]["body"] + + +def test_an_unparseable_body_still_names_the_status(sink): + """A proxy answering HTML has no `reason` to take — the line must still be worth reading, and + must still not fall back to printing the body.""" + resp = httpx.Response( + 502, + text="Bad Gateway", + request=httpx.Request("GET", "https://www.googleapis.com/youtube/v3/search"), + ) + err = _upstream_failure("GET", "search", resp) + + (line,) = sink.at("WARNING") + assert line["attrs"] == { + "method": "GET", + "path": "search", + "status": 502, + "reason": "", + } + assert "Bad Gateway" not in str(err) + assert isinstance(err, YouTubeError) + + +def test_a_sign_in_names_the_account_by_id_and_not_by_address(client, make_user, sink): + make_user(email="signing.in@example.com", password="correct horse battery") + + r = client.post( + "/auth/password-login", + json={"email": "signing.in@example.com", "password": "correct horse battery"}, + ) + assert r.status_code == 200 + + (line,) = [o for o in sink.at("INFO") if o.get("event") == "auth.login.ok"] + assert line["attrs"]["method"] == "password" + assert isinstance(line["attrs"]["uid"], int) + # Not `[email]` either: the redacted form is what made the old line useless. + assert "signing.in" not in json.dumps(line) + assert logs.REDACTED_EMAIL not in json.dumps(line) + + +# --- the family ------------------------------------------------------------------------------ +# Names that hold something a person typed or a place they went. A log call may still pass one — +# `main.py` logs the instance's OWN setup URL — but it has to say so on the line, which is the +# difference between a decision and an oversight. +_BANNED_NAMES = frozenset( + { + "term", + "q", + "query", + "search_term", + "email", + "emails", + "recipients", + "recipient", + "url", + "webpage_url", + "source_url", + "source_webpage_url", + "password", + } +) +_BANNED_ATTRS = frozenset({"text", "content", "email", "url", "query"}) +_ESCAPE = "log-pii-ok" +_LOG_METHODS = frozenset( + {"debug", "info", "warning", "warn", "error", "exception", "critical", "log"} +) + + +def _is_log_call(node: ast.AST) -> bool: + if not isinstance(node, ast.Call) or not isinstance(node.func, ast.Attribute): + return False + if node.func.attr not in _LOG_METHODS: + return False + base, name = node.func.value, "" + while isinstance(base, ast.Attribute): + name = f"{base.attr}.{name}" + base = base.value + if isinstance(base, ast.Name): + name = f"{base.id}.{name}" + return "log" in name.lower() + + +def _offending(node: ast.Call) -> set[str]: + found: set[str] = set() + for sub in ast.walk(node): + if isinstance(sub, ast.Name) and sub.id in _BANNED_NAMES: + found.add(sub.id) + elif isinstance(sub, ast.Attribute) and sub.attr in _BANNED_ATTRS: + found.add(f".{sub.attr}") + return found + + +def test_no_log_call_passes_what_a_person_typed(): + root = pathlib.Path(__file__).resolve().parents[1] / "app" + offenders = [] + for path in sorted(root.rglob("*.py")): + src = path.read_text(encoding="utf-8") + lines = src.splitlines() + for node in ast.walk(ast.parse(src)): + if not _is_log_call(node): + continue + names = _offending(node) + if not names: + continue + # The call's own lines plus the one directly above it — a marker belongs either + # on the argument or on the comment line introducing the call, and nowhere + # further, or one call's justification would excuse its neighbour. + start = max(0, node.lineno - 2) + span = " ".join(lines[start : (node.end_lineno or node.lineno)]) + if _ESCAPE in span: + continue + offenders.append(f"{path.relative_to(root)}:{node.lineno} {sorted(names)}") + assert offenders == [], ( + "a log call carries user-typed content; log an id or a reason code instead, or mark " + f"the argument (or the line directly above the call) `# {_ESCAPE}: ` — {offenders}" + )