From dc221338bedce4ce731c63645879d3ae928407f9 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Fri, 18 Sep 2026 00:49:43 +0200 Subject: [PATCH 1/8] fix(logs): keep what a person typed out of the backend log lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The E22 redactor is a safety net over addresses and credential params, and every one of these call sites was leaning on it to do the whole job. What it does not cover went in whole, and what it does cover came out as a constant. Not covered, so a real leak: - routes/search.py logged the raw search term at ERROR. The privacy policy shipped in 0.88.0 says a search string is kept only at Teljes/TRACE, with the user's own consent. The ERROR line now carries the shape of the failure (source, candidate and collected counts) and the term follows on a TRACE line, which nothing emits unless that consent is in force. - downloads/backfill.py logged the full source URL at INFO — a row of the user's download history. Now the asset id and the host. - youtube/client.py logged the upstream error body, which is prose that quotes the request back. Every failing YouTube call now goes through one _upstream_failure() that logs the API's `reason` code, keeps the body for the same consented TRACE line, and raises a YouTubeError carrying `reason` as a field — callers put that error in log lines of their own (routes/channels.py) and in a 422 answered to the user, so the body must not travel in it either. Covered, so merely useless: routes/auth.py named the account by an address that reached both sinks as `[email]`, and app/email.py printed recipient lists that read as `['[email]']`. Both now carry the uid (or a count) and a reason code, which is also the first half of E22.5 S4's failed-sign-in coverage. routes/channels.py branched on the text of that error message to recognise an already-existing subscription. It now branches on `exc.reason`, with the substring check kept beside it for a body that carried no reason at all. tests/test_log_pii.py pins the call sites and the family: a source-level contract test walks every log call in app/ and fails on an argument naming user-typed content unless the line says why it is safe (`# log-pii-ok: `). Eight sites carry that marker today, each with its reason. Gate 8/8 green; all five cases mutation-checked. --- backend/app/downloads/backfill.py | 18 ++- backend/app/email.py | 16 ++- backend/app/main.py | 2 +- backend/app/routes/auth.py | 40 ++++-- backend/app/routes/channels.py | 10 +- backend/app/routes/search.py | 25 +++- backend/app/youtube/client.py | 72 ++++++++-- backend/tests/test_log_pii.py | 213 ++++++++++++++++++++++++++++++ 8 files changed, 364 insertions(+), 32 deletions(-) create mode 100644 backend/tests/test_log_pii.py 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}" + ) From 0cff964ff253dd0a659c31fa4dc1dbc106a15430 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Fri, 18 Sep 2026 00:57:57 +0200 Subject: [PATCH 2/8] refactor(logs): name every logger after its module, and hold it there MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 25 literal names covered 34 modules. plex/client.py, plex/stream.py, plex/subtitles.py, plex/sync.py and two Plex route modules all called themselves `siftlode.plex`; downloads/pipeline.py called itself `siftlode.worker`; routes/channels.py called itself `siftlode.api`. The `logger` column is in every stored row so E22.6's console can filter on it, and so an operator can pin a level to one part of the system — neither works when six modules share a name. `logs.get_logger(__name__)` derives it: app/plex/sync.py -> siftlode.plex.sync. One name per module, and it cannot drift from the file it sits in. tests/test_logger_names.py pins the derivation, that everything stays under the one `siftlode` tree the handler and the tests attach to, and that no module hand-rolls a name again unless the line says why (`# logger-name-ok: `). Two do: get_logger's own call, and `siftlode.http`, which is named for the traffic it carries rather than the module it lives in — it replaced uvicorn's access log and is what an operator pins when they want request lines and nothing else. app/scheduler.py called its logger `logger`; every other module calls it `log`. ruff gains LOG, G, T20, TRY400, TRY401 and S112. Four findings cleared with them: worker.py logged `str(exc)[:120]` where the traceback was the whole question, and three prints/f-strings that are deliberate now say so on the line. S110 and BLE001 stay off until S3 — 23 handlers are outstanding and each is a judgement about one of them; enabling the rules first would just mean 23 blanket noqas. --- backend/app/auth.py | 4 +- backend/app/downloads/backfill.py | 4 +- backend/app/downloads/credentials.py | 4 +- backend/app/downloads/edit.py | 8 +-- backend/app/downloads/gc.py | 6 +-- backend/app/downloads/pipeline.py | 5 +- backend/app/downloads/runner.py | 9 ++-- backend/app/email.py | 6 +-- backend/app/logs.py | 21 +++++++- backend/app/logsink.py | 10 ++-- backend/app/main.py | 4 +- backend/app/plex/client.py | 5 +- backend/app/plex/stream.py | 6 +-- backend/app/plex/subtitles.py | 5 +- backend/app/plex/sync.py | 6 +-- backend/app/plex/tmdb.py | 6 +-- backend/app/plex/watch_sync.py | 6 +-- backend/app/realtime.py | 4 +- backend/app/routes/channels.py | 5 +- backend/app/routes/plex/_shared.py | 5 +- backend/app/routes/plex/people.py | 4 +- backend/app/routes/search.py | 4 +- backend/app/scheduler.py | 22 ++++---- backend/app/state.py | 5 +- backend/app/sync/autotag.py | 7 ++- backend/app/sync/explore.py | 5 +- backend/app/sync/maintenance.py | 6 +-- backend/app/sync/playlists.py | 6 +-- backend/app/sync/runner.py | 2 +- backend/app/sync/subscriptions.py | 4 +- backend/app/sysconfig.py | 6 +-- backend/app/worker.py | 15 +++--- backend/app/youtube/client.py | 4 +- backend/ruff.toml | 15 ++++++ backend/tests/test_logger_names.py | 79 ++++++++++++++++++++++++++++ backend/tests/test_logsink.py | 4 +- scripts/e2e_seed.py | 3 +- 37 files changed, 204 insertions(+), 116 deletions(-) create mode 100644 backend/tests/test_logger_names.py diff --git a/backend/app/auth.py b/backend/app/auth.py index 2dae04ba..ab9bd6ac 100644 --- a/backend/app/auth.py +++ b/backend/app/auth.py @@ -1,5 +1,3 @@ -import logging - import httpx from fastapi import BackgroundTasks, Depends, HTTPException, Request from sqlalchemy import delete, func, select @@ -39,7 +37,7 @@ READ_SCOPES = f"{BASE_SCOPES} {READ_SCOPE}" WRITE_SCOPES = f"{BASE_SCOPES} {READ_SCOPE} {WRITE_SCOPE}" _YOUTUBE_SCOPES = frozenset({READ_SCOPE, WRITE_SCOPE}) -log = logging.getLogger("siftlode.auth") +log = logs.get_logger(__name__) def google_enabled(db: Session) -> bool: diff --git a/backend/app/downloads/backfill.py b/backend/app/downloads/backfill.py index b4de7c6a..ef17ed03 100644 --- a/backend/app/downloads/backfill.py +++ b/backend/app/downloads/backfill.py @@ -11,12 +11,12 @@ Run once per environment: docker exec siftlode-worker-1 python -c "from app.downloads import backfill; print(backfill.run())" """ -import logging from urllib.parse import urlsplit import yt_dlp from sqlalchemy import select +from app import logs from app.config import settings from app.db import SessionLocal from app.downloads import adapters @@ -24,7 +24,7 @@ from app.downloads import edit as editmod from app.downloads import formats, service from app.models import MediaAsset -log = logging.getLogger("siftlode.backfill") +log = logs.get_logger(__name__) def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: diff --git a/backend/app/downloads/credentials.py b/backend/app/downloads/credentials.py index c3e20ebb..bce4ca4c 100644 --- a/backend/app/downloads/credentials.py +++ b/backend/app/downloads/credentials.py @@ -23,19 +23,19 @@ Security controls enforced here: logged, or written to a job's error/snapshot. """ -import logging import os from pathlib import Path from sqlalchemy import select from sqlalchemy.orm import Session +from app import logs from app.downloads import formats from app.downloads.adapters import _host_is from app.models import DownloadCredential, MediaAsset from app.security import decrypt_optional, encrypt -log = logging.getLogger("siftlode.downloads.credentials") +log = logs.get_logger(__name__) class HostSpec: diff --git a/backend/app/downloads/edit.py b/backend/app/downloads/edit.py index aabeba7b..161591a9 100644 --- a/backend/app/downloads/edit.py +++ b/backend/app/downloads/edit.py @@ -23,7 +23,6 @@ for a player hover-preview later. import hashlib import json -import logging import math import os import queue @@ -33,9 +32,10 @@ import threading import time from pathlib import Path +from app import logs from app.config import settings -log = logging.getLogger("siftlode.edit") +log = logs.get_logger(__name__) def encode_thread_cap() -> int: @@ -368,7 +368,9 @@ def escalate_kill(proc: subprocess.Popen, terminate, kill, grace_s: float, label try: proc.wait(timeout=grace_s) except subprocess.TimeoutExpired: - log.error("%s pid %s survived SIGKILL", label, proc.pid) + # noqa TRY400: the exception IS the message here. A TimeoutExpired's traceback is this + # `wait` call and nothing else — it would add three frames and no fact the line lacks. + log.error("%s pid %s survived SIGKILL", label, proc.pid) # noqa: TRY400 def _stop(proc: subprocess.Popen) -> None: diff --git a/backend/app/downloads/gc.py b/backend/app/downloads/gc.py index a640c22e..f3a4e6a1 100644 --- a/backend/app/downloads/gc.py +++ b/backend/app/downloads/gc.py @@ -16,7 +16,6 @@ Five passes each run: Runs in the API process (which mounts DOWNLOAD_ROOT). Pure disk/DB work — no YouTube quota. """ -import logging import time from datetime import datetime, timedelta, timezone from pathlib import Path @@ -24,14 +23,13 @@ from pathlib import Path from sqlalchemy import func, select from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.downloads import storage from app.models import DownloadJob, MediaAsset from app.notifications import create_notification -log = logging.getLogger("siftlode.downloads.gc") - +log = logs.get_logger(__name__) # Dot-prefixed top-level trees that are NOT part of the Plex/flat asset layout — the orphan sweep # never touches them (user clips, Plex HLS/img caches, in-progress staging, editor storyboards). _SYSTEM_TREE = {".edits", ".plex-hls", ".plex-img-cache", ".staging", ".storyboards"} diff --git a/backend/app/downloads/pipeline.py b/backend/app/downloads/pipeline.py index 758d2f4f..c9692a84 100644 --- a/backend/app/downloads/pipeline.py +++ b/backend/app/downloads/pipeline.py @@ -1,6 +1,5 @@ """Child-side download/edit pipeline — the yt-dlp download + ffmpeg edit that runs in the spawned subprocess.""" -import logging import re import shutil import time @@ -9,7 +8,7 @@ from pathlib import Path import yt_dlp -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.db import SessionLocal from app.downloads import edit as editmod @@ -29,7 +28,7 @@ from app.models import DownloadJob, MediaAsset from app.notifications import create_notification from app.titles import normalize_title -log = logging.getLogger("siftlode.worker") +log = logs.get_logger(__name__) class _Aborted(Exception): diff --git a/backend/app/downloads/runner.py b/backend/app/downloads/runner.py index 0e1c70cd..84d04c28 100644 --- a/backend/app/downloads/runner.py +++ b/backend/app/downloads/runner.py @@ -11,7 +11,6 @@ writes the terminal job/asset state itself (done / error, or a cooperative pause progress hook), then exits 0. An unexpected crash exits non-zero and the parent fails the job. """ -import logging import os import shutil import subprocess @@ -24,7 +23,7 @@ from app.db import SessionLocal from app.downloads import edit as editmod from app.models import DownloadJob -log = logging.getLogger("siftlode.worker.runner") +log = logs.get_logger(__name__) def _deprioritize() -> None: @@ -57,7 +56,11 @@ def main() -> None: logs.configure_logging("runner") _deprioritize() if len(sys.argv) != 2: - print("usage: python -m app.downloads.runner ", file=sys.stderr) + # noqa T201: this runs BEFORE configure_logging, and a usage error has to reach the + # operator who typed it whether or not logging was ever set up. + print( # noqa: T201 + "usage: python -m app.downloads.runner ", file=sys.stderr + ) raise SystemExit(2) job_id = int(sys.argv[1]) # This whole process exists to run ONE job — tag every line it prints with it, so the child's diff --git a/backend/app/email.py b/backend/app/email.py index 860a89d5..8b92813a 100644 --- a/backend/app/email.py +++ b/backend/app/email.py @@ -11,7 +11,6 @@ to be a person telling them nothing arrived. """ import html -import logging import re import smtplib import ssl @@ -21,15 +20,14 @@ from email.utils import formatdate from sqlalchemy import select from sqlalchemy.orm import Session -from app import mailtext, sysconfig +from app import logs, mailtext, sysconfig from app.config import settings from app.db import SessionLocal from app.models import User from app.notifications import create_notification from app.ratelimit import RateLimiter -log = logging.getLogger("siftlode.email") - +log = logs.get_logger(__name__) # One admin notice an hour per reason. A relay that is down fails every send, and the inbox must # stay readable; the log keeps the full record either way. _alert_throttle = RateLimiter(max_events=1, window_seconds=3600) diff --git a/backend/app/logs.py b/backend/app/logs.py index 700c6aa6..11fc15b7 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -15,7 +15,7 @@ issue attachment will carry, so it is deliberately flat and stable. Call sites stay ordinary stdlib logging: - log = logging.getLogger("siftlode.downloads") + log = logs.get_logger(__name__) # app/downloads/pipeline.py -> siftlode.downloads.pipeline log.info("job finished", extra=logs.event("download.job.done", job_id=7, bytes=n)) `event()` is optional — a bare `log.info("…")` still comes out well-formed — but the dotted code is @@ -401,6 +401,20 @@ _THIRD_PARTY_LEVELS = { } +def get_logger(name: str) -> logging.Logger: + """The logger for one module: `logs.get_logger(__name__)` in `app/plex/sync.py` is + `siftlode.plex.sync`. + + The names were literals before, and 25 of them covered 34 modules — six different Plex modules + all called themselves `siftlode.plex`, so neither a level pinned per logger nor E22.6's console + filter could tell a sync line from a stream line. Derived from `__name__` there is exactly one + name per module, it cannot drift from the file it sits in, and `test_logger_names.py` fails if a + module hand-rolls one again.""" + stem = name.removeprefix("app.") if name.startswith("app.") else "" + # logger-name-ok: this call IS the derivation + return logging.getLogger(f"siftlode.{stem}" if stem else "siftlode") + + def resolve_level(name: str) -> int: """Level name → number. Both ways in (the `LOG_LEVEL` env and the `log_level` admin knob) are already held to the `LogLevel` choices, so an unknown name here is a programming error.""" @@ -566,7 +580,10 @@ _REQUEST_ID_RE = re.compile(r"^[A-Za-z0-9._-]{8,64}$") # A FAILURE on either still logs at WARNING/ERROR — this lowers the floor, it does not hide. _QUIET_PREFIXES = ("/healthz", "/assets/", "/static/") -_request_log = logging.getLogger("siftlode.http") +# Not `siftlode.logs`: this is the replacement for uvicorn's ACCESS log, and `siftlode.http` is +# what an operator pins a level on when they want request lines and nothing else. The module it +# happens to live in is not what the name is about. +_request_log = logging.getLogger("siftlode.http") # logger-name-ok: named for the traffic async def log_requests(request, call_next): diff --git a/backend/app/logsink.py b/backend/app/logsink.py index 444fe5bd..edd65157 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -66,7 +66,7 @@ _LIMITS = { "exc": 32_000, } -_log = logging.getLogger("siftlode.logsink") +_log = logs.get_logger(__name__) def should_store(record: logging.LogRecord) -> bool: @@ -254,8 +254,12 @@ class LogSink(logging.Handler): with self._bind.connect() as conn, logs.erasure_guard(), conn.begin(): conn.execute(insert(LogEvent), without_erased(rows)) except Exception as exc: # noqa: BLE001 — the database is down or refused the batch - print( - f"log sink: could not store {len(rows)} log events: {logs.redact_text(str(exc))[:300]}", + # noqa T201: the sink's OWN failure. A log call here would be handed to this sink, + # which is the thing that just failed — straight into a loop. stderr is the one way + # out that does not re-enter. + print( # noqa: T201 + f"log sink: could not store {len(rows)} log events: " + f"{logs.redact_text(str(exc))[:300]}", file=sys.stderr, ) return 0 diff --git a/backend/app/main.py b/backend/app/main.py index 27cd1176..d0ebc429 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -1,5 +1,4 @@ import asyncio -import logging import math from contextlib import asynccontextmanager, suppress from pathlib import Path @@ -12,11 +11,12 @@ from fastapi.exceptions import RequestValidationError # import time is already covered. ONE format for the api, the worker, the download child and alembic # alike (app/logs.py) — this replaces the old uvicorn --log-config + the hand-rolled fallback that # used to live here, and uvicorn's access log is replaced by the `http.request` middleware below. +from app import logs from app.logs import configure_logging, current_level, log_requests, set_level configure_logging("api") -log = logging.getLogger("siftlode.app") +log = logs.get_logger(__name__) from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import FileResponse, HTMLResponse, JSONResponse from fastapi.staticfiles import StaticFiles diff --git a/backend/app/plex/client.py b/backend/app/plex/client.py index d3313323..23efb475 100644 --- a/backend/app/plex/client.py +++ b/backend/app/plex/client.py @@ -6,16 +6,15 @@ metadata, image proxying, and (P5) optional watch-state write-back. Requests JSO ``Accept: application/json`` header (Plex serves XML by default). """ -import logging from urllib.parse import quote import httpx from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.config import settings -log = logging.getLogger("siftlode.plex") +log = logs.get_logger(__name__) class PlexError(Exception): diff --git a/backend/app/plex/stream.py b/backend/app/plex/stream.py index aec74c3e..db518f02 100644 --- a/backend/app/plex/stream.py +++ b/backend/app/plex/stream.py @@ -18,7 +18,6 @@ segments. The remux is CPU-light (video copy + a tiny audio transcode), so it ru CPU-only prod host; only P3's full transcode is CPU-heavy. """ -import logging import os import re import secrets @@ -31,15 +30,14 @@ from pathlib import Path from sqlalchemy.orm import Session as DbSession -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.downloads.edit import encode_thread_cap from app.models import PlexItem from app.plex import paths from app.plex.sync import HW_DECODABLE_CODECS -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) _HLS_ROOT = ( Path(settings.plex_hls_dir) if settings.plex_hls_dir diff --git a/backend/app/plex/subtitles.py b/backend/app/plex/subtitles.py index 132f476e..c840e687 100644 --- a/backend/app/plex/subtitles.py +++ b/backend/app/plex/subtitles.py @@ -33,7 +33,6 @@ zero-based clock and shifted back to absolute time here with `shift_vtt`. """ import json -import logging import re import subprocess import tempfile @@ -44,6 +43,7 @@ from pathlib import Path from sqlalchemy.orm import Session +from app import logs from app.db import SessionLocal from app.models import PlexItem from app.plex import paths as plex_paths @@ -51,8 +51,7 @@ from app.plex.cache import CACHE_DIR from app.plex.client import PlexClient, PlexError from app.plex.lookups import by_rating_key -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) # Image-based subtitle codecs (Blu-ray/DVD) — can't be turned into text WebVTT (would need burn-in). BITMAP_SUBS = { "pgs", diff --git a/backend/app/plex/sync.py b/backend/app/plex/sync.py index a581a4b0..5f1c1934 100644 --- a/backend/app/plex/sync.py +++ b/backend/app/plex/sync.py @@ -15,20 +15,18 @@ dead `enabled` column) is a separate follow-up. Cast + intro/credit markers are item-detail/player path (P2), not here. """ -import logging from datetime import datetime, timezone from sqlalchemy import func, select from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.models import PlexCollection, PlexItem, PlexLibrary, PlexSeason, PlexShow from app.plex import detail, people from app.plex.client import PlexClient, PlexError, PlexNotConfigured from app.plex.lookups import by_rating_key -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) # Codecs/containers a browser can play in a native