peter/siftlode
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

fix(logs): keep what a person typed out of the backend log lines

Browse Source 
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: <why>`). Eight sites
carry that marker today, each with its reason. Gate 8/8 green; all five cases
mutation-checked.
This commit is contained in:
peter
2026-09-18 00:49:43 +02:00
parent 8c10e57208
commit dc221338be
8 changed files with 364 additions and 32 deletions
Download Patch File Download Diff File Expand all files Collapse all files
backend/app/downloads/backfill.py
+15 -3
View File
@@ -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
backend/app/email.py
+13 -3
View File
@@ -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
backend/app/main.py
+1 -1
View File
@@ -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
backend/app/routes/auth.py
+32 -8
View File
@@ -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 email>")
# 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}
backend/app/routes/channels.py
+9 -1
View File
@@ -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 (`<none>` / `<unparseable>`).
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(
backend/app/routes/search.py
+23 -2
View File
@@ -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(
backend/app/youtube/client.py
+58 -14
View File
@@ -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 "<unparseable>"
return reasons or "<none>"
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:
backend/tests/test_log_pii.py
+213
View File
@@ -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="<html><body>Bad Gateway</body></html>",
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": "<unparseable>",
}
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}: <why it is "
f"safe>` — {offenders}"
)