diff --git a/CHANGELOG.md b/CHANGELOG.md index 51046584..fe84175e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,21 @@ edit the release notes and re-run the generator. Upgrading, pinning a version and rolling back: [docs/self-hosting.md](docs/self-hosting.md#upgrading). +## 0.89.0 — 2026-09-19 + +A release for the log rather than for the screen: what the server writes down when something fails is now complete, said once, and free of what you downloaded or searched for. + +### Fixes + +- A download that failed because the server lost its database for a moment no longer shows the video's title and file path inside the database's own error message. + +### Internal + +- No log line carries what a person typed, watched or downloaded: search terms, titles, channel names, file paths, links and video ids are taken out — also from yt-dlp's and ffmpeg's own text, from error stacks, and from database errors. The one exception is Full diagnostics, and only under the user's own consent. +- Every one of the backend's 114 swallowed exceptions was ruled on: 44 now leave a line with an event code, the other 70 say in the code why they need none — and a test keeps it that way. A failure is logged once, with its stack when it is our own bug, and a stalled or killed download no longer fails without a line. +- yt-dlp's own explanations (“Requested format is not available”, a sign-in wall) reach the log instead of a stdout nobody read, and a burst of identical lines is summarised instead of flooding the stored log. +- Three adversarial review rounds: 49 findings raised, 42 survived three independent attempts to refute them, all fixed, and every regression test was proven to fail with its own fix removed. + ## 0.88.0 — 2026-09-18 When something goes wrong, you can now turn on detailed logging for yourself for 24 hours — and read your own log on the spot, before any of it is sent anywhere. Siftlode also has a privacy policy and terms at last, in both languages, saying exactly what is recorded and for how long. diff --git a/VERSION b/VERSION index fe6d01c1..5aee1345 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -0.88.0 +0.89.0 diff --git a/backend/app/auth.py b/backend/app/auth.py index 2dae04ba..b8044a9c 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: @@ -222,7 +220,7 @@ def revoke_google_token(token: str | None) -> None: timeout=10, ) log.info("Google token revoke: status=%s", resp.status_code) - except Exception: + except Exception: # noqa: BLE001 — a revoke we cannot make must not fail the sign-out log.warning("Google token revoke failed", exc_info=True) @@ -305,6 +303,13 @@ def resolved_user_id(conn: HTTPConnection, *, strict: bool = True) -> tuple[int try: hid = int(hdr) except ValueError: + # Under `strict` this becomes a 401 and the tab authenticates as nobody, which reads + # in the browser exactly like a session that expired. The value itself stays out — + # it came from a request, and `wallet` says which accounts were actually on offer. + log.debug( + "the active-account header could not be read as an id", + extra=logs.event("auth.account_header.invalid", accounts=len(wallet)), + ) hid = None if hid is not None and hid in wallet: return hid, hid == default_id @@ -376,12 +381,20 @@ def optional_current_user(request: Request, db: Session = Depends(get_db)) -> Us user_id, is_default = resolved_user_id(request, strict=False) try: return _session_user(request, db, user_id, is_default) + # silent-ok: this is the anonymous case as much as the refused one — every landing page hit + # comes through here. The second attempt below is the handling, and it reports. except HTTPException: if is_default: return None try: return _session_user(request, db, *resolved_user_id(request, strict=False)) except HTTPException: + # Both the pinned account AND the default one were refused, so the tab is signed out + # without being told why — and it got here from a session that named a real account. + log.info( + "a session was resolved to nobody: neither the named nor the default account held", + extra=logs.event("auth.session.probe_rejected", user_id=user_id), + ) return None diff --git a/backend/app/config.py b/backend/app/config.py index eaa9976e..2b2ad824 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -16,6 +16,8 @@ def _version_from_file() -> str: v = p.read_text(encoding="utf-8").strip() if v: return v + # silent-ok: this runs at import, and `app.logs` imports THIS module — a log call here + # would be a circular import. The loop tries the other location, then falls back to "dev". except OSError: continue return "dev" diff --git a/backend/app/db.py b/backend/app/db.py index 8ca8ecf2..51a06301 100644 --- a/backend/app/db.py +++ b/backend/app/db.py @@ -20,6 +20,10 @@ engine = create_engine( max_overflow=30, pool_timeout=30, future=True, + # A database error renders its bound parameters into its message — a title, an uploader, a + # file path, a URL — and that message is logged and stored as a job's error text. The SQL + # stays; the values are data, and the ids an operator needs are on the line already. + hide_parameters=True, ) SessionLocal = sessionmaker(bind=engine, autoflush=False, expire_on_commit=False) diff --git a/backend/app/discover/pins.py b/backend/app/discover/pins.py index aa79ecd8..7a49ca47 100644 --- a/backend/app/discover/pins.py +++ b/backend/app/discover/pins.py @@ -62,6 +62,8 @@ def resolve_ref(db: Session, user: User, kind: str, ref: str) -> tuple[str, obje return (col, sh.id) if sh is not None else None try: pid = int(ref) + # silent-ok: validating a reference the client supplied. "Not an integer" is answered as "no + # such pin target", which is the same answer this function gives for one that does not exist. except ValueError: return None pl = db.get(Playlist, pid) diff --git a/backend/app/downloads/adapters.py b/backend/app/downloads/adapters.py index 3f0c4ca5..4749adc5 100644 --- a/backend/app/downloads/adapters.py +++ b/backend/app/downloads/adapters.py @@ -18,6 +18,7 @@ import yt_dlp from yt_dlp.networking.impersonate import ImpersonateTarget from app.config import settings +from app.downloads.stated import StatedFailure # Facebook's "Cannot parse data": the page yt-dlp got was a wall, not the content. Both the Chrome retry # below and the failure catalog (errors.py) decide on it, so the wording exists once. @@ -178,11 +179,11 @@ class FacebookAdapter(SourceAdapter): # Measured (E11.5 review): a refused or expired cookie gets the login page (~450 KB, a login # form, no post id at all), which is not a post without a video — the user's cookie is the cause. if _quoted(post_id) not in page: - raise RuntimeError(POST_NOT_SHOWN_MESSAGE) + raise StatedFailure(POST_NOT_SHOWN_MESSAGE) video_id = facebook_post_video_id(page, post_id) if video_id is None: # Never fall back to the post link: that is exactly where the wrong video comes from. - raise RuntimeError(POST_WITHOUT_VIDEO_MESSAGE) + raise StatedFailure(POST_WITHOUT_VIDEO_MESSAGE) return f"https://www.facebook.com/watch/?v={video_id}" def client_sets(self, authed: bool = False) -> list: diff --git a/backend/app/downloads/backfill.py b/backend/app/downloads/backfill.py index 76d8258c..b793a770 100644 --- a/backend/app/downloads/backfill.py +++ b/backend/app/downloads/backfill.py @@ -11,11 +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 @@ -23,12 +24,17 @@ 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) -> 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).""" + with formats.hiding(url): + return _extract_meta_scoped(url, adapter, asset_id) + + +def _extract_meta_scoped(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: for clients in adapter.client_sets(): opts = formats.build_ydl_opts( {}, "%(id)s.%(ext)s", lambda d: None, extra=adapter.ydl_opts_extra(clients) @@ -40,7 +46,19 @@ 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. yt-dlp's message goes through + # `log_safe` for the same reason: it opens with the URL or the video id. + 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, + formats.log_safe(exc)[:100], + ) return None @@ -60,12 +78,14 @@ 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 filled_url += 1 - log.info("asset %s uploader_url <- %s", a.id, uu) + log.info( + "asset %s uploader_url filled", a.id + ) # the URL names what they downloaded if a.poster_path is None: # Record a self-hosted poster for every download (the reliable og:image source): # ensure_poster returns the existing .jpg thumbnail sidecar, or cuts a frame. @@ -73,7 +93,7 @@ def run() -> dict: if rel: a.poster_path = rel filled_poster += 1 - log.info("asset %s poster <- %s", a.id, rel) + log.info("asset %s poster filled", a.id) # the path carries the title db.commit() result = { "assets": len(assets), 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..d4967169 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,11 @@ import threading import time from pathlib import Path +from app import logs from app.config import settings +from app.downloads.stated import StatedFailure -log = logging.getLogger("siftlode.edit") +log = logs.get_logger(__name__) def encode_thread_cap() -> int: @@ -71,7 +72,13 @@ def normalize_edit_spec(spec: dict | None) -> dict: if crop: try: c = {k: int(round(float(crop[k]))) for k in ("x", "y", "w", "h")} - except (KeyError, TypeError, ValueError): + except (KeyError, TypeError, ValueError) as exc: + # The clip still renders — uncropped. The user asked for a crop, got a whole frame, + # and nothing anywhere called it a failure; this line is the only trace there is. + log.warning( + "the crop in an edit spec could not be read and was dropped", + extra=logs.event("edit.spec.crop_dropped", reason=type(exc).__name__), + ) c = None if c and c["w"] > 0 and c["h"] > 0 and c["x"] >= 0 and c["y"] >= 0: out["crop"] = c @@ -80,6 +87,7 @@ def normalize_edit_spec(spec: dict | None) -> dict: segs = spec.get("segments") if isinstance(segs, list) and segs: norm: list[dict] = [] + unreadable = 0 for s in segs: try: st = max(0.0, float((s or {}).get("start_s") or 0.0)) @@ -88,9 +96,18 @@ def normalize_edit_spec(spec: dict | None) -> dict: continue en = float(end_raw) except (TypeError, ValueError): + # silent-ok: counted, not logged here — one cut-list can drop several, and the + # join that comes out is simply shorter than the one the user built. Reported + # once after the loop. + unreadable += 1 continue if en > st: norm.append({"start_s": round(st, 3), "end_s": round(en, 3)}) + if unreadable: + log.warning( + "some segments of a cut list could not be read and were dropped", + extra=logs.event("edit.spec.segments_dropped", dropped=unreadable, kept=len(norm)), + ) norm.sort(key=lambda x: x["start_s"]) # SEC-13: an accurate join builds one ffmpeg `filter_complex` with two filters per segment, # so an unbounded list becomes an unbounded command line and an ffmpeg that never finishes. @@ -114,7 +131,13 @@ def normalize_edit_spec(spec: dict | None) -> dict: start = max(0.0, float(trim.get("start_s") or 0.0)) end_raw = trim.get("end_s") end = float(end_raw) if end_raw is not None else None - except (TypeError, ValueError): + except (TypeError, ValueError) as exc: + # Either a 400 the user cannot act on, or — beside a crop — a full-length clip where + # they asked for a cut. Both are worth one line saying the spec was the problem. + log.warning( + "the trim in an edit spec could not be read and was dropped", + extra=logs.event("edit.spec.trim_dropped", reason=type(exc).__name__), + ) start, end = 0.0, None t: dict = {"start_s": round(start, 3)} if end is not None and end > start: @@ -306,11 +329,14 @@ def _parse_out_time(line: str) -> float | None: if line.startswith("out_time_us="): try: return int(line.split("=", 1)[1]) / 1_000_000 + # silent-ok: one line of ffmpeg's `-progress` stream, several per second. None means "this + # line carried no usable time", which the caller already treats as "no progress yet". except ValueError: return None if line.startswith("out_time_ms="): # (some builds mislabel this as microseconds) try: return int(line.split("=", 1)[1]) / 1_000_000 + # silent-ok: as above, the other spelling of the same line. except ValueError: return None return None @@ -329,7 +355,9 @@ def _pump(stream, sink: "queue.Queue[str | None]") -> None: try: for line in stream: sink.put(line) - except (ValueError, OSError): # pipe closed under us by the kill path + # silent-ok: the pipe was closed under us by our OWN kill path — the expected end of a + # cancelled or timed-out run, and the code that did the killing is the code that reports it. + except (ValueError, OSError): pass finally: sink.put(None) @@ -347,6 +375,8 @@ def _drain_tail(stream, sink: list[str]) -> None: sink.append(line) if len(sink) > 200: del sink[:100] + # silent-ok: same closed pipe as `_pump` above, and the tail collected so far is still handed + # to whoever reports the failure. except (ValueError, OSError): pass @@ -362,13 +392,17 @@ def escalate_kill(proc: subprocess.Popen, terminate, kill, grace_s: float, label try: proc.wait(timeout=grace_s) return + # silent-ok: the escalation below IS the handling of this timeout, and surviving THAT is what + # the line under the second wait reports. except subprocess.TimeoutExpired: pass kill() 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: @@ -404,6 +438,8 @@ def run_ffmpeg( while True: try: line = lines.get(timeout=1.0) + # silent-ok: not a failure — the one-second timeout is how this loop gets a turn to + # poll for cancellation while ffmpeg is quiet. except queue.Empty: line = "" if line is None: # stdout hit EOF — ffmpeg is done (or dying) @@ -416,11 +452,11 @@ def run_ffmpeg( if should_cancel(): raise EditAborted if time.monotonic() - last_output > stall_timeout_s: - raise RuntimeError(f"ffmpeg stalled: no progress for {int(stall_timeout_s)}s") + raise StatedFailure(f"ffmpeg stalled: no progress for {int(stall_timeout_s)}s") try: ret = proc.wait(timeout=_FFMPEG_EXIT_GRACE_S) except subprocess.TimeoutExpired: # pipes closed but the process lingers - raise RuntimeError("ffmpeg did not exit after closing its output") + raise StatedFailure("ffmpeg did not exit after closing its output") except BaseException: # ONE exit path stops the process, so the invariant is unconditional: nothing leaves this # function with ffmpeg still running. Not just our own EditAborted/stall — `on_progress` @@ -435,7 +471,7 @@ def run_ffmpeg( if pipe: pipe.close() if ret != 0: - raise RuntimeError(f"ffmpeg failed ({ret}): {''.join(err_tail)[-300:]}") + raise StatedFailure(f"ffmpeg failed ({ret}): {''.join(err_tail)[-300:]}") # --- ffmpeg: universal browser playability -------------------------------------------------- @@ -471,7 +507,13 @@ def run_ffprobe_json( try: out = subprocess.run(args, capture_output=True, text=True, timeout=30, check=True).stdout return json.loads(out) - except (subprocess.TimeoutExpired, subprocess.CalledProcessError, OSError, ValueError): + except (subprocess.TimeoutExpired, subprocess.CalledProcessError, OSError, ValueError) as exc: + # None makes every field it would have filled read as absent, and a file with no streams + # and no duration is indistinguishable here from one that is not media at all. + log.warning( + "ffprobe could not read a file", + extra=logs.event("media.ffprobe_failed", reason=type(exc).__name__), + ) return None @@ -525,7 +567,13 @@ def probe_duration(path: Path) -> int: check=True, ).stdout.strip() return int(float(out)) if out else 0 - except (subprocess.TimeoutExpired, subprocess.CalledProcessError, OSError, ValueError): + except (subprocess.TimeoutExpired, subprocess.CalledProcessError, OSError, ValueError) as exc: + # Zero is the denominator of the re-encode progress bar, so a failed probe leaves the user + # watching a bar that never moves rather than a job that says it went wrong. + log.info( + "the duration probe failed; progress for this job has no total", + extra=logs.event("media.duration_probe_failed", reason=type(exc).__name__), + ) return 0 @@ -670,15 +718,28 @@ def _run_ffmpeg_best_effort(cmd: list[str], timeout_s: int) -> Exception | None: try: subprocess.run(cmd, capture_output=True, timeout=timeout_s, check=True) return None + # silent-ok: the exception is the RETURN VALUE. This helper exists so the three callers share + # one run/timeout policy, and each logs the failure with the context only it has. except (subprocess.TimeoutExpired, subprocess.CalledProcessError, OSError) as exc: return exc +def _step_failure(err: BaseException) -> str: + """What a best-effort image step's failure line says: the kind and, for ffmpeg, its exit + status. Never `str(err)`: a CalledProcessError or TimeoutExpired quotes ffmpeg's argv, and an + OSError its file name — the source path either way, which is built from the channel and the + title.""" + code = getattr(err, "returncode", None) + return f"{type(err).__name__} {code}" if code is not None else type(err).__name__ + + def _is_jpeg(path: Path) -> bool: """True if the file starts with the JPEG SOI marker (FF D8 FF).""" try: with path.open("rb") as f: return f.read(3) == b"\xff\xd8\xff" + # silent-ok: False only means "do not copy this straight through" — the caller then goes the + # ffmpeg route, which opens the same file and reports it properly if it really is unreadable. except OSError: return False @@ -699,13 +760,15 @@ def thumbnail_to_jpg(src: Path | None, dest: Path, timeout_s: int = 30) -> Path shutil.copyfile(src, dest) return dest except OSError as exc: - log.info("thumbnail copy failed (%s); poster falls back to a cut frame", str(exc)[:120]) + log.info( + "thumbnail copy failed (%s); poster falls back to a cut frame", _step_failure(exc) + ) return None err = _run_ffmpeg_best_effort(build_thumbnail_jpg_cmd(src, dest), timeout_s) if err is not None: log.info( "thumbnail->jpg conversion failed (%s); poster falls back to a cut frame", - str(err)[:120], + _step_failure(err), ) return None return dest if dest.exists() else None @@ -730,7 +793,7 @@ def ensure_poster(asset, download_root: str, timeout_s: int = 30) -> str | None: at = min(3.0, (asset.duration_s or 10) * 0.1) err = _run_ffmpeg_best_effort(build_poster_cmd(src, dest, at), timeout_s) if err is not None: - log.info("poster gen skipped for asset %s: %s", asset.id, str(err)[:120]) + log.info("poster gen skipped for asset %s: %s", asset.id, _step_failure(err)) return None return rel if dest.exists() else None @@ -761,7 +824,7 @@ def ensure_storyboard(asset, download_root: str, timeout_s: int = 90) -> dict | cmd = build_storyboard_cmd(src, dest, asset.duration_s, geom) err = _run_ffmpeg_best_effort(cmd, timeout_s) if err is not None: - log.info("storyboard gen skipped for asset %s: %s", asset.id, str(err)[:120]) + log.info("storyboard gen skipped for asset %s: %s", asset.id, _step_failure(err)) return None if not dest.exists(): return None diff --git a/backend/app/downloads/formats.py b/backend/app/downloads/formats.py index cc05becf..22e43f50 100644 --- a/backend/app/downloads/formats.py +++ b/backend/app/downloads/formats.py @@ -17,8 +17,134 @@ spec shape (all keys optional; defaults + browser-playability clamp applied by ` `container`/`vcodec` keys survive only so an old stored profile deserializes without error. """ +import contextlib +import contextvars import hashlib import json +import logging +import os +import re +import urllib.parse +from collections.abc import Iterator + +from app import logs + +log = logs.get_logger(__name__) + +# yt-dlp names what it is working on in these shapes, and each one is a row of someone's download +# history: the source URL, the `[extractor] :` prefix on nearly every warning and error, the +# file path it writes to (`storage.rel_path` builds it from the channel and the title), a +# playlist's title, and an id quoted mid-sentence. The job id is already on every line +# (`logs.set_job` in the download child), so none of them adds anything an operator needs. What +# stays: the host (it says which extractor is failing) and the extractor tag. Every pattern below +# is a shape measured in yt-dlp's own source (2026.07.04), pinned in test_ytdlp_logging.py. +_URL_RE = re.compile(r"https?://([^/\s]+)\S*") +# `Destination:` is yt-dlp's own word in `[download] Destination: `, not an id — the path +# after it is what `_PATH_RE` takes out. +_ID_PREFIX_RE = re.compile(r"(\[[\w:.-]+\] )(?!Destination:)[^\s:\[\]]+:") +# The generic extractor's "id" is the URL's basename, percent-DECODED: `My%20Holiday.mp4` is +# `My Holiday` — spaces, brackets, colons and all, which no pattern can bound (`Our Trip: Day 1` +# ends at which `: `?). The job knows its own URL, so the exact name is taken out as a literal +# (`hiding`). This pattern is the fallback for a line logged outside that scope: up to the first +# `: `. Only this extractor: every other one names a site id, and letting the prefix run to `: ` +# everywhere would take the words out of lines like `[VideoConvertor] Converting …; Destination:`. +_GENERIC_ID_RE = re.compile(r"(\[generic\] )(?!Destination:)[^\[\]\n]+?:(?= |$)", re.M) +# `[youtube:tab] Playlist : Downloading 5 items` — the title is not an id, and has spaces. +_PLAYLIST_TITLE_RE = re.compile(r"(\] Playlist ).+?(?=: Downloading )") +# `[download] Finished downloading playlist: <title>`, `[download] Downloading playlist: <title>`, +# `… Skipping already downloaded playlist: <title>` — the title runs to the end of the line. +_TITLE_TAIL_RE = re.compile(r"(playlist: |\[download\] Downloading \w+: ).*", re.I) +# An id quoted mid-sentence, not as a prefix: `… not available for <id>`, and `--no-playlist`'s +# `Downloading just the video <id>` (`_yes_playlist`) / `Downloading just video <id>` (multifeed). +_BARE_ID_RE = re.compile( + r"((?:subtitles not available for|Downloading just (?:the )?\w+) )[^\s,;]+" +) +# Two segments or more, and not glued to a word: `www.youtube.com/…` is what the URL pattern +# leaves behind, and it must survive this one. +_PATH_RE = re.compile(r"(?<![\w.…])/(?:[^/\s\"']+/)+[^/\s\"']*") + + +_HIDDEN: contextvars.ContextVar[tuple[str, ...]] = contextvars.ContextVar( + "formats_hidden", default=() +) + + +def generic_id(url: str) -> str: + """The name yt-dlp's generic extractor gives a URL: its basename, extension off, percent- + decoded — `InfoExtractor._generic_id` (2026.07.04), pinned against it in the tests.""" + return urllib.parse.unquote(os.path.splitext(url.rstrip("/").split("/")[-1])[0]) + + +@contextlib.contextmanager +def hiding(url: str | None) -> Iterator[None]: + """For the work on one URL: `log_safe` also takes out the name yt-dlp's generic extractor + gives it, exactly, where yt-dlp puts it (`[generic] <name>:`). A context variable, so it + holds for yt-dlp's logger calls too — they run on the same thread as the extraction.""" + name = generic_id(url) if url else "" + token = _HIDDEN.set((*_HIDDEN.get(), name) if name else _HIDDEN.get()) + try: + yield + finally: + _HIDDEN.reset(token) + + +def log_safe(text: object) -> str: + """yt-dlp's text (its own lines, or a DownloadError's message) with the parts that name a + person's download taken out. Every log line that carries yt-dlp's words goes through here, + not just the adapter's: yt-dlp raises the same text it has just logged, so a line that skipped + it would put back one line later exactly what the adapter took out.""" + text = str(text) + for name in _HIDDEN.get(): + text = text.replace(f"[generic] {name}:", "[generic] …:") + text = _URL_RE.sub(lambda m: f"{m.group(1)}/…", text) + text = _ID_PREFIX_RE.sub(r"\1…:", text) + text = _GENERIC_ID_RE.sub(r"\1…:", text) + text = _PLAYLIST_TITLE_RE.sub(r"\1…", text) + text = _TITLE_TAIL_RE.sub(r"\1…", text) + text = _BARE_ID_RE.sub(r"\1…", text) + return _PATH_RE.sub("…", text) + + +class _YdlLog: + """yt-dlp's logger protocol, pointed at ours. + + Without it yt-dlp explains itself to nobody: `quiet` sends its output to a stdout we do not + read, so "Requested format is not available", a signature-extraction failure or a POT refusal + reached us only as whatever text ended up in the raised exception. Measured against yt-dlp + 2026.07.04: with `logger` set it calls `debug` for extraction and progress lines and + `warning`/`error` for the rest, and `quiet`/`no_warnings` do NOT gate those calls. + + `debug` goes to TRACE: it is several lines per second during a download, so it shows only + when the whole process runs at TRACE. (Not under a user's own Teljes consent — that lives in + the API process's request scope, and the download child that runs yt-dlp has none.) + + `error` goes to WARNING, not ERROR. yt-dlp calls it from `trouble()` just before it raises, + on EVERY failed attempt — including the ones the pipeline then recovers from with its fallback + client set. Whether the job failed is the pipeline's verdict (`download.job.failed`), and that + is the one line whose level should say so.""" + + def _emit(self, level: int, msg: str) -> None: + # The line goes as an ARGUMENT, not as the format string. yt-dlp writes progress as + # `[download] 53.2% of 12.00MiB`, and while stdlib logging only applies `%` formatting to + # a record that has args, this way the question never arises — and it is the shape ruff's + # `G` rules ask for. (The sink's flood limiter groups a bare `%s` by the text itself, so + # distinct yt-dlp warnings do not share one bucket — `logsink._template`.) + log.log(level, "%s", log_safe(msg), extra=logs.event("download.ytdlp")) + + def debug(self, msg): + self._emit(logs.TRACE, msg) + + def info(self, msg): + self._emit(logging.DEBUG, msg) + + def warning(self, msg): + self._emit(logging.WARNING, msg) + + def error(self, msg): + self._emit(logging.WARNING, msg) + + +_YDL_LOG = _YdlLog() # Fields that affect the produced file — and therefore the cache identity. _SIG_KEYS = ( @@ -78,7 +204,13 @@ def normalize(spec: dict) -> dict: # rather than raising an unhandled 500 at enqueue. try: s["max_height"] = int(s["max_height"]) - except (TypeError, ValueError): + except (TypeError, ValueError) as exc: + # "best" is the opposite of what a height cap asks for: the user set a ceiling to save + # bandwidth or disk, and the download quietly takes the largest rendition there is. + log.warning( + "the height cap on a download could not be read and was dropped", + extra=logs.event("download.format.max_height_dropped", reason=type(exc).__name__), + ) s["max_height"] = None for b in ("embed_subs", "embed_chapters", "embed_thumbnail", "sponsorblock"): s[b] = bool(s[b]) @@ -181,6 +313,12 @@ def build_ydl_opts( if extra: opts.update(extra) + # With a logger attached, `quiet` and `no_warnings` stop deciding whether yt-dlp explains itself + # and only decide where — so both stay on above and the explanation comes here instead of to a + # stdout nothing reads. AFTER the adapter merge, like `cookiefile` and the size cap: an adapter + # must not be able to silence the one account of what went wrong that a failed job leaves. + opts["logger"] = _YDL_LOG + # SEC-13: hard ceiling on a single download. AFTER the adapter merge, for the same reason # `cookiefile` is — a source adapter must not be able to raise a limit the quota layer set. # diff --git a/backend/app/downloads/gc.py b/backend/app/downloads/gc.py index a640c22e..60267f98 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"} @@ -99,6 +97,7 @@ def _sweep_orphan_files(db: Session, download_root: str) -> int: if pause_s and touched % batch == 0: time.sleep(pause_s) + unreclaimed = 0 for entry in root.iterdir(): if entry.name.startswith("."): # .edits / .plex-* / .staging / .storyboards + any dotfile continue @@ -111,7 +110,9 @@ def _sweep_orphan_files(db: Session, download_root: str) -> int: f.unlink() removed += 1 except OSError: - pass + # silent-ok: counted, not logged per file — a broken mount would put one line + # under every orphan. The total is reported once at the end of the sweep. + unreclaimed += 1 if entry.is_dir(): # prune emptied dirs (deepest first), then the channel dir itself for d in sorted( (p for p in entry.rglob("*") if p.is_dir()), @@ -120,12 +121,20 @@ def _sweep_orphan_files(db: Session, download_root: str) -> int: ): try: d.rmdir() + # silent-ok: `rmdir` refusing means the directory still holds files, which is + # the ordinary answer here — this prune only takes the ones that emptied. except OSError: pass try: entry.rmdir() + # silent-ok: the same prune one level up, at the channel directory. except OSError: pass + if unreclaimed: + log.warning( + "some orphaned download files could not be reclaimed", + extra=logs.event("download.gc.unreclaimed", files=unreclaimed, removed=removed), + ) return removed diff --git a/backend/app/downloads/links.py b/backend/app/downloads/links.py index 41b3cdd5..0f023774 100644 --- a/backend/app/downloads/links.py +++ b/backend/app/downloads/links.py @@ -49,6 +49,8 @@ def check_grant(token: str, grant: str | None, password_version: int) -> bool: exp_s, sig = grant.split(".", 1) try: exp = int(exp_s) + # silent-ok: an untrusted grant that does not parse is simply not a valid grant, and the + # honest answer to it — a password prompt — is the same as for one that expired. except ValueError: return False if exp < datetime.now(timezone.utc).timestamp(): diff --git a/backend/app/downloads/og.py b/backend/app/downloads/og.py index b9babc41..29d1e9aa 100644 --- a/backend/app/downloads/og.py +++ b/backend/app/downloads/og.py @@ -66,6 +66,8 @@ def _jpeg_size(path: Path) -> tuple[int, int] | None: width = (data[3] << 8) + data[4] return width, height f.seek(length - 2, 1) # skip this segment's payload + # silent-ok: None omits width/height from the unfurl card, which is what the card does for + # every poster whose dimensions were never asked for. Nothing is claimed that is not true. except OSError: return None diff --git a/backend/app/downloads/pipeline.py b/backend/app/downloads/pipeline.py index 758d2f4f..d61e99b6 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 @@ -24,12 +23,13 @@ from app.downloads.jobdb import ( _staging_dir, _touch_job, ) +from app.downloads.stated import StatedFailure from app.downloads.status import JobStatus 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): @@ -98,6 +98,8 @@ def _parse_upload_date(raw) -> date | None: return None try: return datetime.strptime(str(raw), "%Y%m%d").date() + # silent-ok: a date we cannot read becomes a date the card does not show, which is what the + # card shows for every source that never supplies one. Absent is the honest rendering. except ValueError: return None @@ -138,7 +140,14 @@ def _make_progress_hook(job_id: int, asset_id: int): try: _fill_asset_meta_early(asset_id, d["info_dict"]) except Exception: # noqa: BLE001 — metadata is best-effort, never fail a download - pass + # Best-effort is about the DOWNLOAD, not about knowing. What this swallows is + # anything from a shape change in yt-dlp's info dict to the database being down, + # and all the user sees is a card with an id on it until the job finishes. + log.info( + "early metadata could not be filled in for this download", + extra=logs.event("download.meta.early_fill_failed", asset_id=asset_id), + exc_info=True, + ) if d.get("status") != "downloading": return if not allow_write(): @@ -299,7 +308,7 @@ def _produced_file(info: dict, staging: Path) -> Path: and not _YTDLP_TEMP_RE.search(p.name) ] if not cands: - raise RuntimeError("yt-dlp produced no output file") + raise StatedFailure("yt-dlp produced no output file") return max(cands, key=lambda p: p.stat().st_size) @@ -375,13 +384,22 @@ def _extract_with_fallback( "job %s: clients %s failed (%s); retrying with fallback", job_id, clients, - str(exc)[:70], + formats.log_safe(exc)[:70], ) for p in list(staging.iterdir()): # drop partials before the retry try: p.unlink() - except OSError: - pass + except OSError as exc: + # A partial left behind is not inert: the next client set resumes into it, + # so the retry this loop exists to make clean starts dirty instead. + log.info( + "a partial file could not be removed before the retry", + extra=logs.event( + "download.retry.partial_unlink_failed", + job_id=job_id, + reason=type(exc).__name__, + ), + ) _set_job(job_id, progress=0, phase="downloading") continue raise @@ -464,7 +482,7 @@ def _download( try: urlguard.check_url(url) except urlguard.BlockedUrl as e: - raise RuntimeError(f"Refusing to download from this address ({e.reason}).") from e + raise StatedFailure(f"Refusing to download from this address ({e.reason}).") from e # S6: attach the acting user's per-host cookie ONLY when it's host-scoped to this URL AND # this asset is that user's private, salted identity (the double gate lives in credentials). remaining_bytes: int | None = None @@ -586,13 +604,23 @@ def _download( db.commit() if finalized: _notify_download_done(db, owner_id, meta.title, job_id, kind="download") - log.info("job %s done: %s", job_id, rel) + # The asset id, not `rel`: the path is built from the channel and the title. + log.info( + "job %s done: asset %s", + job_id, + asset_id, + extra=logs.event("download.job.done", job_id=job_id, asset_id=asset_id), + ) except (_Aborted, editmod.EditAborted): # Paused/canceled mid-download or mid-transcode: free the asset for a later retry; keep the # job's status (the route set it to paused/canceled). ref_count is adjusted by the route. _reset_asset_pending(asset_id) - log.info("job %s aborted (pause/cancel)", job_id) + log.info( + "job %s aborted (pause/cancel)", + job_id, + extra=logs.event("download.job.aborted", job_id=job_id), + ) except _OwnerRefused as exc: # Fail this job only. The asset is never marked `error`; it goes back to `pending` (below), # so another user's job for the same video is claimed and downloaded normally instead of @@ -613,7 +641,12 @@ def _download( # it, and this one must already be out of the way. (The staging tree is still torn down in # `finally` below — the same narrow window the pause/cancel path above has always had.) _reset_asset_pending(asset_id) - log.info("job %s refused for its owner: %s", job_id, msg) + log.info( + "job %s refused for its owner: %s", + job_id, + formats.log_safe(msg), + extra=logs.event("download.job.refused", job_id=job_id), + ) except Exception as exc: # noqa: BLE001 — surface any failure to the user, keep worker alive msg = str(exc)[:500] # The catalog needs the link and whether the user's cookie went with it: the same yt-dlp @@ -626,8 +659,9 @@ def _download( if asset: asset.status = "error" asset.error = msg - # Atomic fail: only while still running, so a route-set cancel/pause is never overwritten - # with `error` (error also holds the asset → would re-open the double-release class). + # Atomic fail: only while still running, so a route-set cancel/pause is never + # overwritten with `error` (error also holds the asset → would re-open the + # double-release class). service.finalize_if_running( db, job_id, @@ -638,7 +672,10 @@ def _download( phase=None, ) db.commit() - log.warning("job %s failed: %s", job_id, msg) + # After the write: a job the write could not fail is not a failed job. When it raises, + # the runner reports this failure with it (`runner._run`) and the worker fails the job. + # silent-ok: not silent — `_log_download_failed` is the report. + _log_download_failed(job_id, msg, diagnosis.code, exc) finally: # Unlink the decrypted cookie file explicitly (the rmtree below removes the whole staging # tree too, but never leave a plaintext session cookie on disk a moment longer than needed). @@ -647,7 +684,50 @@ def _download( shutil.rmtree(staging, ignore_errors=True) -def _fail_edit(job_id: int, asset_id: int, msg: str) -> None: +def _failure_stack(exc: BaseException) -> dict[str, str]: + """The `extra=` fragment that puts a failure's traceback on its line — or nothing. + + Nothing for yt-dlp's DownloadError and for our own `StatedFailure` (`ffmpeg failed (1): …`): + their message is the whole story, and their stack is only the `except` that caught them. + Everything else keeps it — a TypeError on an odd info dict, a plain RuntimeError, an OSError, + a database error: that is our code or our platform failing, and the stack is the lead. + + Scrubbed, link by link (`logs.scrubbed_stack`): a stack's messages are data — an OSError names + its file, and a database error raised inside `except DownloadError` carries yt-dlp's + unscrubbed text as its context.""" + if isinstance(exc, (yt_dlp.utils.DownloadError, StatedFailure)): + return {} + return logs.scrubbed_stack(exc, formats.log_safe) + + +def _log_download_failed(job_id: int, msg: str, code: str | None, exc: BaseException) -> None: + """The child's `download.job.failed` line. `msg` is the user's copy and keeps their URL; the + log's copy goes through `log_safe`, or it would put back one line later the URL and id the + yt-dlp adapter took out of the line before it. The stack only when the classifier could not + place the failure: a recognised one is fully described by its code.""" + unplaced = code in (None, "", "unknown") + log.warning( + "job %s failed: %s", + job_id, + formats.log_safe(msg), + extra={ + **logs.event( + "download.job.failed", + job_id=job_id, + error_code=code, + error_type=type(exc).__name__, + ), + **(_failure_stack(exc) if unplaced else {}), + }, + ) + + +def _fail_edit(job_id: int, asset_id: int, msg: str, exc: BaseException | None = None) -> None: + """Fail an edit job, and say so ONCE — every way an edit fails comes through here, so this is + where its line and its event code live. `exc` is the exception when there was one. + + Its traceback goes with the line unless the message already tells it all (`_failure_stack`). + Logged after the write, as on the download error path.""" with SessionLocal() as db: asset = db.get(MediaAsset, asset_id) if asset: @@ -663,7 +743,22 @@ def _fail_edit(job_id: int, asset_id: int, msg: str) -> None: phase=None, ) db.commit() - log.warning("edit job %s failed: %s", job_id, msg) + # `msg` is the user's copy; ffmpeg's stderr tail in it can name the source file, whose path is + # built from the channel and the title. + log.warning( + "edit job %s failed: %s", + job_id, + formats.log_safe(msg), + extra={ + **logs.event( + "edit.job.failed", + job_id=job_id, + asset_id=asset_id, + **({"error_type": type(exc).__name__} if exc is not None else {}), + ), + **(_failure_stack(exc) if exc is not None else {}), + }, + ) def _process_edit(job_id: int, asset_id: int) -> None: @@ -715,7 +810,7 @@ def _process_edit(job_id: int, asset_id: int) -> None: should_cancel=_cancel_poll(job_id), ) if not dest_staging.exists(): - raise RuntimeError("ffmpeg produced no output file") + raise StatedFailure("ffmpeg produced no output file") rel = storage.edit_rel_path(user_id, asset_id, out_ext) storage.place_file(dest_staging, settings.download_root, rel) @@ -751,13 +846,24 @@ def _process_edit(job_id: int, asset_id: int) -> None: db.commit() if finalized: _notify_download_done(db, owner_id, dl_title, job_id, kind="edit") - log.info("edit job %s done: %s", job_id, rel) + # The asset id, not `rel`: the path is built from the channel and the title. + log.info( + "edit job %s done: asset %s", + job_id, + asset_id, + extra=logs.event("edit.job.done", job_id=job_id, asset_id=asset_id), + ) except editmod.EditAborted: # Paused/canceled mid-encode: free the asset for a later retry (ref_count is the route's job). _reset_asset_pending(asset_id) - log.info("edit job %s aborted (pause/cancel)", job_id) + log.info( + "edit job %s aborted (pause/cancel)", + job_id, + extra=logs.event("edit.job.aborted", job_id=job_id), + ) except Exception as exc: # noqa: BLE001 — surface the failure, keep the worker alive - _fail_edit(job_id, asset_id, str(exc)[:500]) + # silent-ok: not silent — `_fail_edit` is the report, and it takes `exc` for its stack. + _fail_edit(job_id, asset_id, str(exc)[:500], exc) finally: shutil.rmtree(staging, ignore_errors=True) diff --git a/backend/app/downloads/probe.py b/backend/app/downloads/probe.py index 4187d00c..04dd70d3 100644 --- a/backend/app/downloads/probe.py +++ b/backend/app/downloads/probe.py @@ -64,6 +64,8 @@ def _facts_from_probe( raw = fmt.get("duration") if raw is not None: duration = int(float(raw)) + # silent-ok: an unusable duration is stored as no duration, which the UI renders as unknown + # rather than as zero — the honest state, and the one a re-probe can still fill in. except (TypeError, ValueError): duration = None return vcodec, acodec, width, height, duration diff --git a/backend/app/downloads/runner.py b/backend/app/downloads/runner.py index 0e1c70cd..ac87b6c1 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 @@ -22,9 +21,10 @@ from app import logsink from app.config import settings from app.db import SessionLocal from app.downloads import edit as editmod +from app.downloads import formats from app.models import DownloadJob -log = logging.getLogger("siftlode.worker.runner") +log = logs.get_logger(__name__) def _deprioritize() -> None: @@ -57,7 +57,12 @@ def main() -> None: logs.configure_logging("runner") _deprioritize() if len(sys.argv) != 2: - print("usage: python -m app.downloads.runner <job_id>", file=sys.stderr) + # noqa T201: a usage line is for the person who typed the command. Logging is already + # configured here, and in a deployment it writes JSON records — the one reader of this + # line wants the bare sentence, not a record with a request id they do not have. + print( # noqa: T201 + "usage: python -m app.downloads.runner <job_id>", 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 @@ -77,14 +82,40 @@ def main() -> None: if asset_id is None: return + _run(job_id, asset_id, job_kind, source_kind, source_ref, spec, user_id) + + +def _run(job_id, asset_id, job_kind, source_kind, source_ref, spec, user_id) -> None: + """Run the job, and be the last stop before Python's own exception hook. + + What gets past the pipeline is a failure it could not even record (the database refused the + write that fails the job). Python's hook would print it to stderr raw — and its context is the + download's own failure, whose text is the URL or ffmpeg's stderr naming the file. Here it is + one line with the whole chain scrubbed; the non-zero exit then has the worker fail the job + (`cause=child_exit`).""" # Imported here (not at module top) so the child pays the yt-dlp import cost only when it has # real work, and to keep the import graph obvious: runner is a thin entry over the pipeline. from app.downloads.pipeline import _download, _process_edit - if job_kind == "edit": - _process_edit(job_id, asset_id) - else: - _download(job_id, asset_id, source_kind, source_ref, spec, user_id) + with formats.hiding(source_ref): + try: + if job_kind == "edit": + _process_edit(job_id, asset_id) + else: + _download(job_id, asset_id, source_kind, source_ref, spec, user_id) + except Exception as exc: # noqa: BLE001 — whatever it is, it is reported here or raw + # noqa TRY400: the stack goes with it scrubbed (`scrubbed_stack`); `exc_info` is raw. + log.error( # noqa: TRY400 + "the download child for job %s failed", + job_id, + extra={ + **logs.event( + "download.child.failed", job_id=job_id, error_type=type(exc).__name__ + ), + **logs.scrubbed_stack(exc, formats.log_safe), + }, + ) + raise SystemExit(1) from None if __name__ == "__main__": diff --git a/backend/app/downloads/service.py b/backend/app/downloads/service.py index 96918e0f..896d65ac 100644 --- a/backend/app/downloads/service.py +++ b/backend/app/downloads/service.py @@ -87,6 +87,8 @@ def get_or_create_asset( with db.begin_nested(): db.add(asset) db.flush() + # silent-ok: the expected outcome of the race this savepoint exists for — two jobs wanting the + # same asset. Losing it means the other insert won, and re-selecting is the whole handling. except IntegrityError: asset = db.execute(stmt).scalar_one() return asset diff --git a/backend/app/downloads/stated.py b/backend/app/downloads/stated.py new file mode 100644 index 00000000..e4a2c991 --- /dev/null +++ b/backend/app/downloads/stated.py @@ -0,0 +1,13 @@ +"""The failures the download pipeline raises itself, with the whole story in the message. + +`ffmpeg failed (1): …`, `yt-dlp produced no output file`, a post that shows no video: the message +says what happened, and the stack is only the `except` that caught it. A failure line leaves that +stack off (`pipeline._failure_stack`) — but ONLY for these. A plain `RuntimeError` is also what +Python raises for a bug of ours (a dict changed size during iteration, a generator's +StopIteration, `RecursionError`, `NotImplementedError`), and that one's stack is the only lead. +""" + + +class StatedFailure(RuntimeError): + """A failure we raised on purpose, whose message is its full explanation. A `RuntimeError` so + every `except RuntimeError` that caught these before still does.""" diff --git a/backend/app/downloads/storage.py b/backend/app/downloads/storage.py index 88ee8577..0084938e 100644 --- a/backend/app/downloads/storage.py +++ b/backend/app/downloads/storage.py @@ -19,8 +19,11 @@ from datetime import date from pathlib import Path from xml.sax.saxutils import escape +from app import logs from app.downloads import mediakind +log = logs.get_logger(__name__) + # Reserve room for the "_id.ext" suffix + parent dirs within the 255-char component limit. _MAX_TITLE = 120 # User-facing (Content-Disposition) names can be longer than an on-disk component. @@ -294,7 +297,13 @@ def write_sidecars(download_root: str, rel: str, meta: MediaMeta, thumb_src: Pat if thumb_src and thumb_src.exists(): shutil.copyfile(str(thumb_src), str(_sidecar(media, ".jpg"))) return True - except OSError: + except OSError as exc: + # The download itself still completes, so the job reads as done while the library it was + # downloaded FOR has no .nfo to read and no poster to show. + log.warning( + "the sidecars beside a download could not be written", + extra=logs.event("download.sidecars.write_failed", reason=type(exc).__name__), + ) return False @@ -304,14 +313,23 @@ def delete_asset_files(download_root: str, rel: str) -> None: for p in (media, _sidecar(media, ".nfo"), _sidecar(media, ".jpg")): try: p.unlink() - except OSError: - pass + except FileNotFoundError: + pass # silent-ok: already gone is the outcome this function wanted + except OSError as exc: + # The row goes and the bytes stay. Nothing else ever revisits this path, so the disk + # quietly keeps a file no account has any way to see, let alone delete. + log.info( + "a deleted download left a file behind", + extra=logs.event("download.asset.file_unlink_failed", reason=type(exc).__name__), + ) # Prune empty Season/Channel dirs up to (but not including) the root. root = Path(download_root).resolve() parent = media.parent while parent != root and root in parent.parents: try: parent.rmdir() # only succeeds if empty + # silent-ok: this `rmdir` failing is the loop's stop condition — the parent still + # holds another download's files, so the prune has gone as far up as it may. except OSError: break parent = parent.parent diff --git a/backend/app/email.py b/backend/app/email.py index 1c08e0e4..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) @@ -155,7 +153,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 +182,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/logs.py b/backend/app/logs.py index 700c6aa6..013076ed 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 @@ -37,7 +37,9 @@ import re import sys import threading import time +import traceback import uuid +from collections.abc import Callable from datetime import datetime, timezone from typing import Any from urllib.parse import parse_qsl @@ -152,11 +154,15 @@ def bind(**fields: Any): _CONTEXT_VARS[key].reset(token) -def event(code: str, **attrs: Any) -> dict[str, Any]: +def event(code: str, /, **attrs: Any) -> dict[str, Any]: """`extra=` payload for a log call: a stable dotted event code plus structured attributes. Returns a plain dict so it composes with stdlib logging and costs nothing when the level is off - (the dict is built either way; keep the attrs cheap — no DB reads inside the call).""" + (the dict is built either way; keep the attrs cheap — no DB reads inside the call). + + `code` is positional-only so that no attribute name is reserved: `event("x", code=...)` means + the attribute, not this parameter. Without the `/` it was a TypeError, and `code` is exactly + the word a caller reaches for when the thing that failed has one of its own.""" return {"event": code, "attrs": attrs} @@ -259,11 +265,53 @@ def redact(value: Any, *, key: str = "") -> Any: # --- formatters ---------------------------------------------------------------------------- +_SCRUBBED_STACK = "scrubbed_stack" + + +def scrubbed_stack(exc: BaseException, scrub: Callable[[BaseException], str]) -> dict[str, str]: + """`extra=` fragment: `exc`'s traceback, rendered where an `exc_info` stack goes, with the + message of every exception in it put through `scrub`. + + For a failure whose message can name someone's data (a download's URL, a file path, a video + id). The frames name code and are kept whole; the text at the foot of each link is the data. + A plain `exc_info` renders the chain too — the `__cause__`/`__context__` a DB error raised + inside `except DownloadError` carries — so scrubbing only the line's own message is not + enough. Merge it into the call's `extra`: `{**event(...), **scrubbed_stack(...)}`.""" + links: list[BaseException] = [] + link: BaseException | None = exc + while link is not None and all(link is not seen for seen in links): + links.append(link) + link = link.__cause__ or (None if link.__suppress_context__ else link.__context__) + parts: list[str] = [] + for i in range(len(links) - 1, -1, -1): # the oldest first, as Python prints a chain + link = links[i] + kind = type(link) + name = kind.__qualname__ + if kind.__module__ not in ("builtins", "__main__"): + name = f"{kind.__module__}.{name}" + try: + message = scrub(link) + # silent-ok: the message is what could not be rendered, and the placeholder says so — the + # caller is in the middle of reporting one failure and must not get a second from here. + except Exception: # noqa: BLE001 — a `__str__` that raises, of any shape + message = "<unprintable>" + frames = "".join(traceback.format_tb(link.__traceback__)) + head = f"Traceback (most recent call last):\n{frames}" if frames else "" + parts.append(f"{head}{name}: {message}" if message else f"{head}{name}") + if i: + parts.append( + "\nThe above exception was the direct cause of the following exception:\n" + if links[i - 1].__cause__ is link + else "\nDuring handling of the above exception, another exception occurred:\n" + ) + return {_SCRUBBED_STACK: "\n".join(parts)} + + # Attributes every LogRecord carries; anything else a caller passed via `extra=` is a structured # attribute and is merged into `attrs` (so `extra={"job_id": 7}` works as well as `event(...)`). _RECORD_STANDARD = frozenset( vars(logging.LogRecord("", 0, "", 0, "", None, None)).keys() - | {"message", "asctime", "taskName", "event", "attrs", PERSIST, "elevated"} + | {"message", "asctime", "taskName", "event", "attrs", PERSIST, "elevated", _SCRUBBED_STACK} ) @@ -314,6 +362,8 @@ def _safe_message(record: logging.LogRecord) -> str: must not take down the caller, so the failure is reported IN the line instead.""" try: return record.getMessage() + # silent-ok: the failure is reported IN the returned line. Logging it would re-enter this same + # formatter with a record built out of the one that just failed. except Exception as exc: # noqa: BLE001 — any formatting error, reported not raised return f"{record.msg!r} (log formatting failed: {exc})" @@ -342,6 +392,8 @@ def record_fields(record: logging.LogRecord) -> dict[str, Any]: fields["attrs"] = redact(attrs) if record.exc_info: fields["exc"] = redact_text(logging.Formatter().formatException(record.exc_info)) + elif getattr(record, _SCRUBBED_STACK, None): + fields["exc"] = redact_text(getattr(record, _SCRUBBED_STACK)) elif record.exc_text: # A QueueHandler-style hand-off formats the traceback into exc_text and drops exc_info. fields["exc"] = redact_text(record.exc_text) @@ -375,6 +427,8 @@ class TextFormatter(logging.Formatter): line += f" {json.dumps(redact(attrs), ensure_ascii=False, default=str)}" if record.exc_info: line += "\n" + redact_text(self.formatException(record.exc_info)) + elif getattr(record, _SCRUBBED_STACK, None): + line += "\n" + redact_text(getattr(record, _SCRUBBED_STACK)) return line @@ -401,6 +455,28 @@ _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. + + `__main__` is resolved to the module it really is. The worker runs as `python -m app.worker` + and spawns `python -m app.downloads.runner`, so in the two long-running processes `__name__` + is `__main__` — taken at its word, both would log as the bare root. `-m` records the real name + on the module's spec; a plain script has none and stays the root.""" + if name == "__main__": + spec = getattr(sys.modules.get("__main__"), "__spec__", None) + name = getattr(spec, "name", None) or name + 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 +642,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): @@ -646,6 +725,16 @@ async def log_requests(request, call_next): return response +def consented_trace() -> bool: + """Whether the current request's OWN user turned Teljes (TRACE) on — the gate for a line that + carries what they typed or what was quoted back to them. The level alone is not enough: an + admin running the whole process at TRACE would pass it for every user, and a scheduler thread, + which has no request, for none of them in particular. Guard such a line with this, then log it + at TRACE.""" + scope = _scope.get() + return scope is not None and _traced(scope) + + def _traced(scope: _RequestScope) -> bool: """Whether this request's query string is logged: only under its OWN user's Teljes consent. An admin setting the whole process to TRACE gets more detail, not every user's search terms — the diff --git a/backend/app/logsink.py b/backend/app/logsink.py index 444fe5bd..924475ee 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -29,6 +29,7 @@ import atexit import json import logging import queue +import re import sys import threading import time @@ -66,7 +67,7 @@ _LIMITS = { "exc": 32_000, } -_log = logging.getLogger("siftlode.logsink") +_log = logs.get_logger(__name__) def should_store(record: logging.LogRecord) -> bool: @@ -137,6 +138,21 @@ def _notice(code: str, msg: str, **attrs: Any) -> dict[str, Any]: ) +_DIGITS = re.compile(r"\d+") + + +def _template(record: logging.LogRecord) -> str: + """The flood limiter's grouping key: the message template. Except when the template is a bare + `%s` — a pass-through for someone else's text (yt-dlp's lines, `formats._YdlLog`), where the + template says nothing and every distinct line would share one bucket. Then the text itself + groups, with its numbers folded, so `Retrying fragment 5 (1/10)` and `(2/10)` are still one + repeat and a different warning is not crowded out by them.""" + msg = str(record.msg) + if msg != "%s" or not record.args: + return msg + return _DIGITS.sub("#", record.getMessage())[:200] + + class _Repeats: """Per-template admission for one minute at a time. Used by the writer thread only (unlocked).""" @@ -155,9 +171,11 @@ class _Repeats: self.seen[key] = (count or 0) + 1 return self.seen[key] <= self.per_window - def roll(self, now: float) -> list[dict[str, Any]]: - """Close the window if it is over: one notice per template that went past the limit.""" - if now - self.started < self.window: + def roll(self, now: float, *, final: bool = False) -> list[dict[str, Any]]: + """Close the window if it is over — or, `final`, because the process is: one notice per + template that went past the limit. Without `final` a process that lives under a minute + (every download child) would drop its repeats and never say so.""" + if not final and now - self.started < self.window: return [] notices = [ _notice( @@ -202,6 +220,8 @@ class LogSink(logging.Handler): return try: row = to_row(logs.record_fields(record)) + # silent-ok: `handleError` is the report — logging's own out-of-band channel to stderr. + # A log call here would be handed to this handler, which is the one that just failed. except Exception: # noqa: BLE001 — a record we cannot turn into a row is reported, not raised self.handleError(record) return @@ -209,21 +229,25 @@ class LogSink(logging.Handler): key = ( None if row["event"] == "http.request" - else (record.name, str(record.msg), record.levelno) + else (record.name, _template(record), record.levelno) ) try: self._queue.put_nowait((key, row)) + # silent-ok: counted, not logged — the count goes out as the `log.sink.dropped` notice row + # the writer emits, which is the one report that does not feed this queue again. except queue.Full: with self._dropped_lock: self._dropped += 1 # --- writer side --------------------------------------------------------------------------- - def write_pending(self, wait: float = 0.0) -> int: + def write_pending(self, wait: float = 0.0, *, final: bool = False) -> int: """Write one batch: whatever is queued (up to BATCH_MAX), waiting up to `wait` seconds for the - first item. Returns the number of rows written, notices included.""" + first item. Returns the number of rows written, notices included. `final` closes the + repeat window early — the last batch before the process exits.""" rows: list[dict[str, Any]] = [] try: item = self._queue.get(timeout=wait) if wait > 0 else self._queue.get_nowait() + # silent-ok: an idle sink. Nothing failed; there was simply nothing waiting. except queue.Empty: item = None while item is not None: @@ -234,9 +258,10 @@ class LogSink(logging.Handler): break try: item = self._queue.get_nowait() + # silent-ok: the batch ends here because the queue ran dry, which is the normal end. except queue.Empty: item = None - rows.extend(self._repeats.roll(time.monotonic())) + rows.extend(self._repeats.roll(time.monotonic(), final=final)) with self._dropped_lock: dropped, self._dropped = self._dropped, 0 if dropped: @@ -254,8 +279,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]}", + # silent-ok / 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 @@ -266,6 +295,7 @@ class LogSink(logging.Handler): self.write_pending(wait=FLUSH_SECONDS) while self.write_pending(): # drain what arrived before the stop pass + self.write_pending(final=True) # and the repeat notices of a window cut short def start(self) -> None: self._writer = threading.Thread(target=self._run, name="log-sink", daemon=True) diff --git a/backend/app/main.py b/backend/app/main.py index a4c1f44a..5896a885 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 @@ -73,17 +73,17 @@ async def lifespan(app: FastAPI): # booting — an unreachable or not-yet-migrated database has to start into the env level. try: set_level(sysconfig.get_str(db, "log_level")) - except Exception as exc: # noqa: BLE001 — any DB/config failure keeps the bootstrap level - log.warning( - "could not read the stored log level (%s); staying at %s", exc, current_level() - ) + except Exception: # noqa: BLE001 — any DB/config failure keeps the bootstrap level + # With the traceback: this catch spans a connection, a query and a coercion at boot, + # and `%s` of the exception does not say which of them raised. + log.exception("could not read the stored log level; staying at %s", current_level()) if not state.is_configured(db): token = state.rotate_setup_token(db) url = f"{settings.app_base}/setup?token={token}" 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/plex/client.py b/backend/app/plex/client.py index d3313323..8701b6ce 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): @@ -106,7 +105,18 @@ class PlexClient: Best-effort (needs the library's related data) — returns [] if Plex has none.""" try: mc = self._get(f"/library/metadata/{rating_key}/related") - except PlexError: + except PlexError as exc: + # An empty list is also the answer for an item that genuinely has no related titles, + # so the caller cannot tell the two apart — and it deliberately declines to CACHE an + # empty one for exactly that reason. This line is what says which it was. + log.debug( + "the related items for a Plex item could not be read", + extra=logs.event( + "plex.client.related_unavailable", + rating_key=rating_key, + reason=type(exc).__name__, + ), + ) return [] out: list[dict] = [] for hub in mc.get("Hub", []) or []: @@ -139,6 +149,8 @@ class PlexClient: raise PlexError(str(e)) from e try: return (r.json() or {}).get("MediaContainer", {}) or {} if r.content else {} + # silent-ok: the HTTP call already succeeded — this is a write endpoint, and Plex answers + # those with an empty or non-JSON body as a matter of course. except ValueError: return {} diff --git a/backend/app/plex/detail.py b/backend/app/plex/detail.py index 8f03e6fa..7752b7d4 100644 --- a/backend/app/plex/detail.py +++ b/backend/app/plex/detail.py @@ -22,6 +22,8 @@ def rich_detail(meta: dict) -> dict: if str(r.get("image") or "").startswith("imdb://"): try: imdb_rating = round(float(r.get("value")), 1) + # silent-ok: no IMDb score, which is the common and legitimate case — the UI has a + # separate audience score to fall back on and shows nothing if neither exists. except (TypeError, ValueError): pass break diff --git a/backend/app/plex/imgcache.py b/backend/app/plex/imgcache.py index a71256e1..76f20b56 100644 --- a/backend/app/plex/imgcache.py +++ b/backend/app/plex/imgcache.py @@ -11,10 +11,13 @@ The cache directory (``cache.CACHE_DIR``) is shared with the subtitle cache (see from fastapi import Response from sqlalchemy.orm import Session +from app import logs from app.models import PlexCollection, PlexItem, PlexSeason, PlexShow from app.plex.cache import CACHE_DIR from app.plex.lookups import by_rating_key +log = logs.get_logger(__name__) + _EXT_CT = [("jpg", "image/jpeg"), ("png", "image/png"), ("webp", "image/webp")] _CT_EXT = {ct: ext for ext, ct in _EXT_CT} # Target box per variant — Plex resizes to these server-side. Posters fill ≤176px cells (grid/info/ @@ -46,6 +49,8 @@ def read(key: str) -> tuple[bytes, str] | None: try: if p.exists() and p.stat().st_size > 0: return p.read_bytes(), ct + # silent-ok: a miss. The caller fetches from Plex and writes the file again, and the write + # path below is the one that reports a cache that cannot be used. except OSError: pass return None @@ -58,8 +63,14 @@ def write(key: str, data: bytes, ct: str) -> None: tmp = CACHE_DIR / f"{key}.{ext}.tmp" tmp.write_bytes(data) tmp.replace(CACHE_DIR / f"{key}.{ext}") # atomic publish - except OSError: - pass # cache is best-effort + except OSError as exc: + # Best-effort, and silently so: with an unwritable cache every poster on every grid goes + # to Plex live, for as long as nobody notices. Debug, because a grid is ~100 images and + # the point is the condition, not the count. + log.debug( + "the Plex image cache could not be written", + extra=logs.event("plex.imgcache.write_failed", reason=type(exc).__name__), + ) def response(data: bytes, ct: str) -> Response: diff --git a/backend/app/plex/paths.py b/backend/app/plex/paths.py index 3c93feaa..9f9eaaf6 100644 --- a/backend/app/plex/paths.py +++ b/backend/app/plex/paths.py @@ -12,7 +12,9 @@ from pathlib import Path from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig + +log = logs.get_logger(__name__) def parse_map(raw: str) -> list[tuple[str, str]]: @@ -47,6 +49,13 @@ def local_media_path(db: Session, plex_path: str | None) -> Path | None: return None try: p = Path(map_path(db, plex_path)).resolve() - except OSError: + except OSError as exc: + # None is answered as a 404 "no local file", which is also the answer for a title the + # server does not hold — so a dead mount or a wrong path map reads as missing media for + # the whole library at once. The path itself stays out: it carries the title. + log.warning( + "a Plex media path could not be resolved locally", + extra=logs.event("plex.paths.resolve_failed", reason=type(exc).__name__), + ) return None return p if p.is_file() else None diff --git a/backend/app/plex/stream.py b/backend/app/plex/stream.py index aec74c3e..9975e1be 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 @@ -135,6 +133,8 @@ class HlsSession: # single index. Derived, not passed, so it cannot disagree with the argv. self.entry = _MASTER_PL if self.variants else _INDEX_PL self.last_access = time.time() + # `artifact_may_arrive` reports a refusing session directory once, not per segment. + self.probe_failure_reported = False def _seek_opts(start_s: float) -> list[str]: @@ -232,7 +232,15 @@ def _probe_video_kind(src: Path) -> str: text=True, timeout=10, ) - except (subprocess.SubprocessError, OSError): + except (subprocess.SubprocessError, OSError) as exc: + # The safe kind is a real answer, but it is the answer for an 8-bit SDR source — a blind + # ffprobe sends every HDR file down it, so playback quietly degrades to a software + # transcode with nothing anywhere saying why. The path stays out of the line: it is the + # title of whatever is playing. + log.info( + "video-kind probe failed; assuming the HW-safe pipeline", + extra=logs.event("plex.stream.probe_kind_failed", reason=type(exc).__name__), + ) return _VK_HWSAFE pix_fmt = bits = transfer = "" for line in out.stdout.splitlines(): @@ -261,7 +269,14 @@ def _opencl_present() -> bool: software libx264. Its own function so it's monkeypatchable in tests, mirroring _render_node_present.""" try: return any(_OPENCL_ICD_DIR.glob("*.icd")) - except OSError: + except OSError as exc: + # A MISSING directory does not come through here — `glob` simply yields nothing for one. + # This is a directory we cannot read, and the answer it forces (no OpenCL) costs every HDR + # source the hardware tonemap path. + log.info( + "the OpenCL ICD directory could not be read; treating OpenCL as absent", + extra=logs.event("plex.stream.opencl_probe_failed", reason=type(exc).__name__), + ) return False @@ -447,6 +462,8 @@ def _sw_child_preexec() -> None: playback.""" try: os.nice(_SW_TRANSCODE_NICE) + # silent-ok: this runs in the forked child, between fork and exec. Logging there can deadlock + # on a lock some other thread held at fork time, and the child is about to become ffmpeg. except OSError: pass @@ -473,7 +490,14 @@ def _probe_audio_langs(src: Path) -> list[str]: timeout=10, ) return [ln.strip() for ln in out.stdout.splitlines()] - except (subprocess.SubprocessError, OSError): + except (subprocess.SubprocessError, OSError) as exc: + # An empty list IS the single-audio path, so a failed probe silently collapses a file with + # several audio tracks down to one — and the viewer gets a player with no language picker + # rather than an error. + log.warning( + "audio-track probe failed; falling back to a single-audio session", + extra=logs.event("plex.stream.probe_audio_failed", reason=type(exc).__name__), + ) return [] @@ -582,8 +606,14 @@ def _probe_first_pts(seg: Path) -> float | None: tok = line.strip().strip(",") if tok: return float(tok) - except (subprocess.SubprocessError, ValueError, OSError): - pass + except (subprocess.SubprocessError, ValueError, OSError) as exc: + # None means "keep the offset the client asked for", and the whole point of this probe is + # that the two differ: without it the subtitle track is shifted by whatever the container + # started its timestamps at. Seconds of drift, and nothing on screen calls it a failure. + log.warning( + "first-PTS probe failed; the requested offset is used as-is", + extra=logs.event("plex.stream.first_pts_probe_failed", reason=type(exc).__name__), + ) return None @@ -592,10 +622,18 @@ def _kill(s: HlsSession) -> None: s.proc.terminate() try: s.proc.wait(timeout=3) + # silent-ok: the escalation IS the handling. A transcode that ignores TERM for three + # seconds gets KILL, which is exactly what this branch does. except subprocess.TimeoutExpired: s.proc.kill() - except Exception: - pass + except Exception as exc: # noqa: BLE001 — teardown finishes whatever the process does + # Not nothing: what survives this is an ffmpeg nobody owns any more, holding a VAAPI + # handle and a core, and the transcode cap that is supposed to bound them counts rows in + # `_sessions` rather than processes. One line is the only way that ever surfaces. + log.info( + "could not stop the transcode process", + extra=logs.event("plex.stream.kill_failed", key=s.key, reason=type(exc).__name__), + ) shutil.rmtree(s.dir, ignore_errors=True) @@ -608,6 +646,13 @@ def _enforce_cap(cap: int) -> None: if len(tx) <= cap: return for key, s in sorted(tx, key=lambda kv: kv[1].last_access)[: len(tx) - cap]: + # Somebody's playback stops here. The route turns the missing session into a retryable + # 404 and the player restarts at the playhead, so from the server nothing failed — and + # "my film keeps rebuffering" has no other explanation anywhere. + log.info( + "a transcode session was dropped to stay under the cap", + extra=logs.event("plex.stream.session_culled", key=key, cap=cap, sessions=len(tx)), + ) _kill(s) _sessions.pop(key, None) @@ -710,6 +755,21 @@ def start_session( tonemap=tonemap, ) _sessions[key] = s + # The one line that says which pipeline a session actually got. Everything downstream + # — the cap, the HW→SW fallback, the subtitle offset — is about this choice, and until + # now it was only inferable from the ffmpeg command nobody keeps. + log.info( + "an HLS session started", + extra=logs.event( + "plex.stream.session_started", + key=key, + transcode=transcode, + hw=hw, + tonemap=tonemap, + variants=len(variants or ()), + start_s=round(start_s, 1), + ), + ) # Admin-configurable concurrency cap (Configuration → Plex → Max concurrent transcodes); # at least 1 so playback can't be capped to zero. _enforce_cap(max(1, sysconfig.get_int(db, "plex_max_transcodes"))) @@ -728,7 +788,8 @@ def start_session( # ONE lock in _spawn, so we can never tear down the newer session. s.hw is now False, so the route # honestly reports "CPU" and the player's Preparing-stream state stays correct. log.warning( - "plex transcode: HW session produced no segments — falling back to software key=%s", key + "the hardware transcode produced no segments; falling back to software", + extra=logs.event("plex.stream.hw_fallback", key=key), ) respawned = _spawn(False, False, replace_only=s) if respawned is None: @@ -867,7 +928,23 @@ def artifact_may_arrive(s: "HlsSession", filename: str) -> bool: return True try: return (s.dir / segment_name(seq - 1, variant)).exists() - except OSError: + except OSError as exc: + # `exists()` answers False for a missing file without raising, so this is the session + # directory itself refusing — a full or unmounted disk. Every segment then 404s, which the + # player shows as a stall. Once per session: this runs for every segment request and + # every hls.js retry of one, and the sink's limiter still stores 30 a minute of a + # template — stdout would get them all. + if not s.probe_failure_reported: + s.probe_failure_reported = True + log.warning( + "a session segment could not be checked", + extra=logs.event( + "plex.stream.segment_probe_failed", + key=s.key, + seq=seq, + reason=type(exc).__name__, + ), + ) return False @@ -884,12 +961,16 @@ def wait_for(path: Path, timeout: float = 20.0, proc: subprocess.Popen | None = try: if path.exists() and path.stat().st_size > 0: return True + # silent-ok: this is a 150 ms poll — a line here is a line every 150 ms for the whole + # timeout. The final check below decides, and the 404 the caller then returns is honest. except OSError: pass if proc is not None and proc.poll() is not None: # the producer exited — no more segments are coming; one last check then give up. try: return path.exists() and path.stat().st_size > 0 + # silent-ok: one last look after the producer exited. False here becomes a 404 the + # player recovers from, which is the honest answer either way. except OSError: return False time.sleep(0.15) @@ -922,7 +1003,16 @@ def sweep_orphans(older_than: float | None = None) -> int: dropped = 0 try: entries = list(_HLS_ROOT.iterdir()) - except OSError: # the root doesn't exist yet — nothing to sweep + # silent-ok: nothing has been transcoded yet, so there is nothing to sweep. + except FileNotFoundError: + return 0 + except OSError as exc: + # Any OTHER reason the root will not list is not "nothing to sweep": the sweep reports 0 + # like a clean run while every crashed session's segments stay on disk forever. + log.warning( + "the HLS root could not be listed; no orphans were swept", + extra=logs.event("plex.stream.sweep_root_unreadable", reason=type(exc).__name__), + ) return 0 for p in entries: if not _SESSION_DIR_RE.match(p.name): @@ -932,7 +1022,9 @@ def sweep_orphans(older_than: float | None = None) -> int: try: if p.stat().st_mtime >= cutoff: continue # this run made (or reused) it — never ours to delete - except OSError: # vanished under us (a concurrent restart of that session) + # silent-ok: vanished under us — a concurrent restart of that session removed it, which + # is the outcome this sweep wanted anyway. + except OSError: continue with _lock: if any(s.dir == p for s in _sessions.values()): diff --git a/backend/app/plex/subtitles.py b/backend/app/plex/subtitles.py index 132f476e..c09e97ec 100644 --- a/backend/app/plex/subtitles.py +++ b/backend/app/plex/subtitles.py @@ -33,17 +33,18 @@ zero-based clock and shifted back to absolute time here with `shift_vtt`. """ import json -import logging import re import subprocess import tempfile import threading import time +import logging from concurrent.futures import ThreadPoolExecutor 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 +52,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", @@ -104,6 +104,7 @@ def shift_vtt(vtt: str, offset: float) -> str: straddling 0 is clamped to start at 0.""" if not offset: return vtt + unshifted = 0 out_blocks: list[str] = [] for block in re.split(r"\n[ \t]*\n", vtt): if "-->" not in block: @@ -121,7 +122,12 @@ def shift_vtt(vtt: str, offset: float) -> str: st = _vtt_ts_to_s(left.strip()) - offset en = _vtt_ts_to_s(rparts[0]) - offset except (ValueError, IndexError): - break # unparseable timing → leave the block as-is + # silent-ok: left as-is means left UNSHIFTED — the viewer sees that one cue at + # the wrong moment. Counted rather than logged here: this is per cue, and the file + # being parsed is one ffmpeg wrote for us a moment ago, so a broken timestamp is + # a fact about the extraction, reported once below. + unshifted += 1 + break if en <= 0: keep = False # whole cue is before the session start → drop the block else: @@ -131,6 +137,11 @@ def shift_vtt(vtt: str, offset: float) -> str: break if keep: out_blocks.append("\n".join(lines)) + if unshifted: + log.info( + "some cues could not be shifted and stay at their original time", + extra=logs.event("plex.subtitles.cues_unshifted", cues=unshifted, offset_s=offset), + ) return "\n\n".join(out_blocks) @@ -162,7 +173,15 @@ def cache_read(key: str) -> str | None: try: p = CACHE_DIR / f"{key}.vtt" return p.read_text(encoding="utf-8") if p.exists() else None - except OSError: + except OSError as exc: + # None is the same answer as "never cached", so a cache we cannot read looks exactly like + # a cold one — and every request re-extracts instead of saying the disk is the problem. + log.warning( + "the cached subtitle could not be read", + extra=logs.event( + "plex.subtitles.cache_read_failed", key=key, reason=type(exc).__name__ + ), + ) return None @@ -175,7 +194,16 @@ def cache_write(key: str, vtt: str) -> bool: tmp.write_text(vtt, encoding="utf-8") tmp.replace(CACHE_DIR / f"{key}.vtt") # atomic publish return True - except OSError: + except OSError as exc: + # `publish` turns False into "the region was not claimed" and moves on, so the track just + # never appears. Which errno it was — full disk, read-only mount, permissions — is the + # whole diagnosis, and it exists only here. + log.warning( + "the subtitle cache could not be written", + extra=logs.event( + "plex.subtitles.cache_write_failed", key=key, reason=type(exc).__name__ + ), + ) return False @@ -206,7 +234,17 @@ def read_meta(key: str) -> tuple[list[list[float]], bool]: try: raw = json.loads(_meta_path(key).read_text(encoding="utf-8")) return [[float(a), float(b)] for a, b in raw.get("ranges", [])], bool(raw.get("complete")) - except (OSError, ValueError, TypeError): + # silent-ok: no sidecar at all is the documented older-build case the fallback exists for. + except FileNotFoundError: + return ([[0.0, _FULL_END_S]], True) if _exists(_vtt_path(key)) else ([], False) + except (OSError, ValueError, TypeError) as exc: + # A sidecar that EXISTS and will not parse is different, and the fallback is the dangerous + # answer to it: beside a cached VTT it reports the track as complete, so a partial track is + # never extended again and the viewer loses every cue past the window that was cached. + log.warning( + "the subtitle sidecar could not be read; the cached track is taken as complete", + extra=logs.event("plex.subtitles.meta_unreadable", key=key, reason=type(exc).__name__), + ) return ([[0.0, _FULL_END_S]], True) if _exists(_vtt_path(key)) else ([], False) @@ -216,6 +254,8 @@ def _exists(p: Path) -> bool: escaped as a 500 from the status route.""" try: return p.exists() + # silent-ok: this function's whole job is to answer False for a path the OS refuses. The + # refusal IS the return value; a caller that needs to report one reports it itself. except (OSError, ValueError): return False @@ -226,8 +266,18 @@ def _write_meta(key: str, ranges: list[list[float]], complete: bool) -> None: tmp = CACHE_DIR / f"{key}.json.tmp" tmp.write_text(json.dumps({"ranges": ranges, "complete": complete}), encoding="utf-8") tmp.replace(_meta_path(key)) - except OSError: - pass + except OSError as exc: + # Without the sidecar beside it, a cached window reads back as a COMPLETE track (see + # `read_meta`) — so one failed write here permanently costs the rest of that subtitle. + log.warning( + "the subtitle sidecar could not be written", + extra=logs.event( + "plex.subtitles.meta_write_failed", + key=key, + complete=complete, + reason=type(exc).__name__, + ), + ) def generation(key: str) -> int: @@ -235,7 +285,9 @@ def generation(key: str) -> int: window is superseded by a wider one the browser refetches instead of keeping the short VTT.""" try: return _vtt_path(key).stat().st_mtime_ns - except (OSError, ValueError): # ValueError: a NUL in the key — `stat` refuses the path outright + # silent-ok: 0 for a track that is not cached yet, which is the ordinary case on every first + # request. (ValueError: a NUL in the key — `stat` refuses the path outright.) + except (OSError, ValueError): return 0 @@ -267,16 +319,27 @@ def merge_vtt(*sources: str) -> str: happen to share a time (two speakers, a sign over dialogue) are both kept.""" seen: set[str] = set() cues: list[tuple[float, str]] = [] + dropped = 0 for src in sources: for block in re.split(r"\n[ \t]*\n", src or ""): - canon = _canonical_cue(block.strip()) + stripped = block.strip() + canon = _canonical_cue(stripped) if canon is None: + # A block WITH a timing line that still would not parse is a cue we are throwing + # away, not a header — and the merged track would simply be missing those lines. + if "-->" in stripped: + dropped += 1 continue # header / NOTE / STYLE — the merged file gets its own single header start, key, text = canon if key in seen: continue seen.add(key) cues.append((start, text)) + if dropped: + log.info( + "some cues were dropped from the merged subtitle: their timing would not parse", + extra=logs.event("plex.subtitles.cues_dropped", cues=dropped, kept=len(cues)), + ) cues.sort(key=lambda c: c[0]) return "WEBVTT\n\n" + "\n\n".join(b for _, b in cues) + "\n" @@ -295,6 +358,8 @@ def _canonical_cue(block: str) -> tuple[float, str, str] | None: try: st = _vtt_ts_to_s(left.strip()) en = _vtt_ts_to_s(rparts[0]) + # silent-ok: None here means "not a cue", and the caller tells a header apart from a + # broken timing line by whether the block had a `-->` at all — see `merge_vtt`. except (ValueError, IndexError): return None lines[i] = f"{_vtt_s_to_ts(st)} --> {_vtt_s_to_ts(en)}{settings}" @@ -310,6 +375,8 @@ def _last_cue_end(vtt: str) -> float: continue try: end = max(end, _vtt_ts_to_s(ln.partition("-->")[2].strip().split(None, 1)[0])) + # silent-ok: this is a floor — "how far the pass provably got". Skipping a line it cannot + # read makes the answer smaller, never larger, so the error is always on the safe side. except (ValueError, IndexError): continue return end @@ -652,12 +719,35 @@ def _run( return _extract_and_publish(rating_key, sub_ord, window_start) except SubtitleUnavailable as e: + # The player's own state was the only place this ever showed. `_pass_failed` backs the item + # off for an hour and `_fail` records a code, but neither leaves a line, so "my subtitles + # never appear" had nothing on the server to read. + # A final code is a fact about the file (no such track, a bitmap subtitle); anything else + # is this instance failing at something it could do. + log.log( + logging.INFO if e.code in FINAL_CODES else logging.WARNING, + "subtitle extraction gave up", + extra=logs.event( + "plex.subtitles.pass_failed", + rating_key=rating_key, + sub_ord=sub_ord, + code=e.code, + windowed=window_start is not None, + ), + ) if e.code == "extract_failed": _pass_failed(rating_key, [key], window_start) else: _fail(key, e.code) except PlexError as e: - log.warning("subtitle extraction failed for %s/%s: %s", rating_key, sub_ord, e) + # No traceback on purpose: a PlexError carries httpx's own message, which names the method, + # the URL and the status — the stack under it is this `except` and the client call, and + # says nothing the message does not. (The URL holds no token; it travels as a header.) + log.warning( + "subtitle extraction failed talking to Plex: %s", + e, + extra=logs.event("plex.subtitles.plex_error", rating_key=rating_key, sub_ord=sub_ord), + ) _fail(key, "plex_error") except ( Exception @@ -829,6 +919,16 @@ def _ffmpeg_extract( try: _, err = proc.communicate(timeout=_TERM_GRACE_S) except subprocess.TimeoutExpired: + # TERM is what makes a timed-out pass worth keeping: ffmpeg closes its outputs + # on it. An ffmpeg that ignores TERM leaves only whole blocks already flushed, + # so the partial track is short for a reason the later line cannot tell apart. + log.info( + "the subtitle extraction ignored TERM and was killed", + extra=logs.event( + "plex.subtitles.extract_killed_after_term", + windowed=start is not None, + ), + ) proc.kill() _, err = proc.communicate() finally: diff --git a/backend/app/plex/sync.py b/backend/app/plex/sync.py index a581a4b0..271a2d9f 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 <video> without any transcoding. _BROWSER_VIDEO = {"h264"} _BROWSER_AUDIO = {"aac", "mp3", "opus", "vorbis"} @@ -102,6 +100,9 @@ def _video_stream_props(meta: dict) -> tuple[int | None, bool]: bd = s.get("bitDepth") try: depth = int(bd) if bd else None + # silent-ok: unknown bit depth, which is also what most listings report. The + # playback class then falls back to the codec alone, and per-stream noise over a + # whole library would drown the sync's own lines. except (TypeError, ValueError): depth = None hdr = str(s.get("colorTrc") or "").lower() in _HDR_TRANSFERS @@ -112,6 +113,8 @@ def _video_stream_props(meta: dict) -> tuple[int | None, bool]: def _epoch(v) -> datetime | None: try: return datetime.fromtimestamp(int(v), tz=timezone.utc) if v else None + # silent-ok: a field Plex leaves out of most listing rows. None is a legitimate stored value, + # and every caller treats it as "not known" rather than as an error. except (TypeError, ValueError, OSError): return None @@ -120,6 +123,7 @@ def _date(v): """Parse a Plex 'YYYY-MM-DD' string (originallyAvailableAt) → date, or None.""" try: return datetime.strptime(v, "%Y-%m-%d").date() if v else None + # silent-ok: as `_epoch` above — an absent or unparsable air date is stored as no air date. except (TypeError, ValueError): return None @@ -135,6 +139,7 @@ def _tags(meta: dict, key: str, limit: int | None = None) -> list | None: def _rating(meta: dict) -> float | None: try: return float(meta.get("audienceRating") or meta.get("rating")) + # silent-ok: TypeError on `float(None)` is the ordinary path — most items carry no rating. except (TypeError, ValueError): return None @@ -266,15 +271,19 @@ def sync(db: Session) -> dict: # becomes filterable over successive runs (the cheap listing above only stored the top ~3). try: stats["people_enriched"] = _enrich_people_batch(db, plex) - except Exception as e: # best-effort — never fail the sync over the backfill - log.warning("Plex people enrich batch failed: %s", e) + except Exception: # noqa: BLE001 — best-effort; never fail the sync over a backfill + # With the traceback: a blind catch over a batch that fetches AND writes can be + # a Plex shape change, a DB error or our own bug, and `%s` told them apart badly. + log.exception("the Plex people-enrich batch failed") # Probe a bounded batch of HW-decodable transcode items for bit-depth/HDR, so the # playback-class filter's HW/SW split is precise (a 10-bit/HDR HEVC → software) over # successive runs. Only HW-decodable-codec transcodes are probed — the rest are SW by codec. try: stats["media_probed"] = _probe_media_batch(db, plex) - except Exception as e: # best-effort — never fail the sync over the backfill - log.warning("Plex media probe batch failed: %s", e) + except Exception: # noqa: BLE001 — best-effort; never fail the sync over a backfill + log.exception("the Plex media-probe batch failed") + # silent-ok: the return value IS the report. `{"skipped": …}` goes to the scheduler, which + # logs the job result, and to the admin route, which answers it to the caller. except PlexNotConfigured as e: return {"skipped": str(e)} except PlexError as e: @@ -285,8 +294,8 @@ def sync(db: Session) -> dict: # appear in ANY item's cast/directors — drop those rows, mirroring how Plex drops orphaned metadata. try: stats["people_pruned"] = people.prune_orphan_people(db) - except Exception as e: # best-effort housekeeping — never fail the sync over it - log.warning("Plex people prune failed: %s", e) + except Exception: # noqa: BLE001 — best-effort housekeeping; never fail the sync over it + log.exception("the Plex people prune failed") log.info("Plex sync done: %s", stats) return stats @@ -325,7 +334,9 @@ def _probe_media_batch(db: Session, plex: PlexClient, limit: int = _PROBE_BATCH) for row in rows: try: meta = plex.metadata(row.rating_key) or {} - except Exception as e: # transient — leave media_probed_at NULL so it retries next run + # No traceback and only debug: this is per item over a whole library, and the stack is + # the same `plex.metadata` call every time. The retry next run is the handling. + except Exception as e: # noqa: BLE001 — transient; leave media_probed_at NULL to retry log.debug("Plex media probe fetch failed for %s: %s", row.rating_key, e) continue bit_depth, hdr = _video_stream_props(meta) @@ -372,7 +383,8 @@ def _enrich_people_batch(db: Session, plex: PlexClient, limit: int = _ENRICH_BAT for row in [*movies, *shows]: try: meta = plex.metadata(row.rating_key) or {} - except Exception as e: + # As in `_probe_media_batch` above: per item, so the message without the stack. + except Exception as e: # noqa: BLE001 — transient; leave people_enriched_at NULL log.debug("Plex people enrich fetch failed for %s: %s", row.rating_key, e) continue # leave people_enriched_at NULL so it's retried on a later run people.enrich_row_people(db, row, people.cast_from_meta(meta)) diff --git a/backend/app/plex/tmdb.py b/backend/app/plex/tmdb.py index 283f5d38..f373d072 100644 --- a/backend/app/plex/tmdb.py +++ b/backend/app/plex/tmdb.py @@ -10,7 +10,6 @@ One-parser rule (mirrors app/plex/detail.py): `parse_tmdb` is the pure parser, ` the row. The enrich batch + scheduler entry live here too so the whole TMDB integration is one module. """ -import logging import time from datetime import datetime, timezone @@ -19,12 +18,11 @@ from sqlalchemy import func, select from sqlalchemy.dialects.postgresql import insert as pg_insert from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.models import PlexItem, PlexPerson, PlexShow -log = logging.getLogger("siftlode.tmdb") - +log = logs.get_logger(__name__) # Politeness throttle: TMDB tolerates ~50 req/s; ~33/s leaves comfortable headroom for a shared host. _MIN_INTERVAL = 0.03 @@ -142,6 +140,12 @@ def guid_to_tmdb_id(guid: str | None, media_type: str, tmdb: TmdbClient) -> int try: return int(ext) except ValueError: + # The caller stamps the watermark on a None, so this title is never looked at again: + # one unreadable guid costs it its artwork and its cast permanently. + log.info( + "a Plex guid named TMDB but did not carry a numeric id", + extra=logs.event("plex.tmdb.guid_unparsable", provider=provider), + ) return None source = {"imdb": "imdb_id", "tvdb": "tvdb_id"}.get(provider) if not source: @@ -499,7 +503,17 @@ def enrich_person(db: Session, person: PlexPerson) -> bool: # doesn't tie up a threadpool worker for the default 30s. with TmdbClient(db, timeout=8.0) as tmdb: payload = tmdb.fetch_person(person.tmdb_person_id) - except TmdbError: + except TmdbError as exc: + # False leaves the person un-enriched and unstamped, so it is retried — but the page in + # front of the user right now shows an empty biography with nothing to say why. + log.warning( + "the TMDB person lookup failed", + extra=logs.event( + "plex.tmdb.person_enrich_failed", + person_id=person.id, + reason=type(exc).__name__, + ), + ) return False if payload is None: person.tmdb_enriched_at = datetime.now(timezone.utc) diff --git a/backend/app/plex/watch_sync.py b/backend/app/plex/watch_sync.py index 0091b9db..47c014d3 100644 --- a/backend/app/plex/watch_sync.py +++ b/backend/app/plex/watch_sync.py @@ -17,14 +17,17 @@ and the incremental pull resolves a genuine divergence to Plex's state (see `_pu running a last-write-wins comparison. """ -import logging +# On the PlexError lines in this module: none of them carries a traceback, deliberately. A +# PlexError is httpx's own message — the method, the URL and the status of one call — and the stack +# beneath it is always this `except` plus `PlexClient._get`. The attrs beside the line say which +# user and which phase, which is the part the message cannot know. from datetime import datetime, timezone from sqlalchemy import func, select, update from sqlalchemy.dialects.postgresql import insert as pg_insert from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.db import SessionLocal from app.models import PlexItem, PlexLink, PlexState from app.plex.client import PlexClient, PlexError, PlexNotConfigured @@ -36,8 +39,7 @@ from app.plex.sync import ( _paginate, ) -log = logging.getLogger("siftlode.plex.watch") - +log = logs.get_logger(__name__) # A resume position below this many seconds isn't worth mirroring — matches the player's own # _PROGRESS_MIN_S (a stray few-second seek is not "in progress"). _PROGRESS_MIN_S = 5 @@ -148,6 +150,8 @@ def import_owner_watch_state(db: Session, link: PlexLink) -> dict: link.initial_import_done = True link.last_watch_sync_at = datetime.now(timezone.utc) db.commit() + # silent-ok: the `{"skipped": …}` return is the report — the admin route answers it and the + # scheduler logs it on the job line. except PlexNotConfigured as e: return {"skipped": str(e)} except PlexError as e: @@ -326,8 +330,18 @@ def _resolve_account_id(db: Session, plex: PlexClient, link: PlexLink) -> int: if int(a.get("id") or -1) == 1: username = a.get("name") break - except PlexError: - pass + except PlexError as exc: + # The fallback account id 1 is right for the admin-token setup, so sync keeps working — + # but the username is never stored, and the UI then has no name to show for the link, + # exactly as if the server had not offered one. + log.info( + "the Plex account list could not be read; the link keeps the default account", + extra=logs.event( + "plex.watch.accounts_probe_failed", + user_id=link.user_id, + reason=type(exc).__name__, + ), + ) link.plex_account_id = acct_id if username: link.plex_username = username @@ -566,6 +580,7 @@ def run_plex_watch_sync(db: Session) -> dict: total["repushed"] += _repush_dirty(db, plex, link) link.last_watch_sync_at = now db.commit() + # silent-ok: the `{"skipped": …}` return is the report, as above. except PlexNotConfigured as e: return {"skipped": str(e)} except PlexError as e: @@ -617,6 +632,7 @@ def run_plex_watch_reconcile(db: Session) -> dict: total["repushed"] += _repush_dirty(db, plex, link) link.last_watch_sync_at = datetime.now(timezone.utc) db.commit() + # silent-ok: the `{"skipped": …}` return is the report, as above. except PlexNotConfigured as e: return {"skipped": str(e)} except PlexError as e: diff --git a/backend/app/ratelimit.py b/backend/app/ratelimit.py index 2e9f3325..6dcef515 100644 --- a/backend/app/ratelimit.py +++ b/backend/app/ratelimit.py @@ -73,6 +73,8 @@ def _norm_ip(s: str) -> ipaddress.IPv4Address | ipaddress.IPv6Address | None: plain-IPv4 allowlist still matches a peer that surfaces in mapped form. None for a non-IP string.""" try: ip = ipaddress.ip_address(s.strip()) + # silent-ok: parsing an untrusted header value, where "not an IP" is a documented answer this + # function returns — and a line per request is what an attacker would aim for. except ValueError: return None return ip.ipv4_mapped if getattr(ip, "ipv4_mapped", None) else ip diff --git a/backend/app/realtime.py b/backend/app/realtime.py index bfe214c4..0f29e086 100644 --- a/backend/app/realtime.py +++ b/backend/app/realtime.py @@ -13,12 +13,12 @@ mutated from a single thread. """ import asyncio -import logging from collections import defaultdict from starlette.websockets import WebSocket +from app import logs -log = logging.getLogger("siftlode.realtime") +log = logs.get_logger(__name__) class ConnectionManager: @@ -42,9 +42,16 @@ class ConnectionManager: for ws in list(self._conns.get(user_id, ())): try: await ws.send_json(payload) - except Exception: - # Stale socket; it'll be cleaned up by its own disconnect handler. - pass + except Exception as exc: # noqa: BLE001 — one dead socket must not stop the others + # Stale socket; it'll be cleaned up by its own disconnect handler. But this is + # also where a live update goes missing: the UI simply never changes, and there + # is no request behind it whose failure anyone could look up. + log.debug( + "a live update could not be pushed to a socket", + extra=logs.event( + "realtime.push_failed", user_id=user_id, reason=type(exc).__name__ + ), + ) def push(self, user_id: int, payload: dict) -> None: """Schedule a push onto the WebSocket event loop. Safe to call from a sync route @@ -54,7 +61,7 @@ class ConnectionManager: return try: asyncio.run_coroutine_threadsafe(self._push(user_id, payload), loop) - except Exception: + except Exception: # noqa: BLE001 — a closed loop or socket must not fail the caller log.debug("ws push failed", exc_info=True) diff --git a/backend/app/routes/auth.py b/backend/app/routes/auth.py index 97bae871..6d135751 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 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} @@ -880,7 +901,12 @@ def _register_account(email: str, password: str, lang: str | None = None) -> Non except IntegrityError: # A concurrent registration for the same new email won the race between the pre-check # above and this flush (the unique-email constraint fires). Same already-registered - # no-op as the pre-check hit — roll back and stop. + # no-op as the pre-check hit — roll back and stop. The line carries nothing: the + # answer to the caller is deliberately identical either way, and so is this. + log.info( + "a registration lost the race for its address", + extra=logs.event("auth.register.race_lost"), + ) db.rollback() return upsert_pending_invite(db, email) # admin-approval gate @@ -1049,7 +1075,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..604bfaf2 100644 --- a/backend/app/routes/channels.py +++ b/backend/app/routes/channels.py @@ -2,7 +2,6 @@ hidden, tags) and per-channel sync state. Local reads/writes plus YouTube-side writes (subscribe / unsubscribe) that require the optional write scope.""" -import logging from datetime import datetime, timezone from fastapi import APIRouter, BackgroundTasks, Depends, HTTPException @@ -10,7 +9,7 @@ from pydantic import BaseModel from sqlalchemy import func, select, update from sqlalchemy.orm import Session -from app import quota +from app import logs, quota from app.auth import admin_user, current_user, require_human, require_write_scope from app.db import get_db from app.models import ( @@ -35,7 +34,7 @@ from app.youtube.client import YouTubeClient, YouTubeError router = APIRouter(prefix="/api/channels", tags=["channels"]) -log = logging.getLogger("siftlode.api") +log = logs.get_logger(__name__) @router.get("") @@ -166,7 +165,15 @@ def discover_channels( user.yt_channel_id = own db.commit() except YouTubeError as exc: - log.warning("discovery: own-channel resolve failed (user %s): %s", user.id, exc) + # No traceback anywhere in this file's YouTube handlers: for an upstream answer + # `_upstream_failure` already logged the structured `youtube.api.error`, and the + # message names the call, its status and its reason (or, with no answer at all, the + # transport failure). The stack under it is this `except` and the client call. + log.warning( + "discovery: own-channel resolve failed: %s", + exc, + extra=logs.event("channels.discovery.own_channel_failed", reason=exc.reason), + ) rows = _discovery_rows(db, user) @@ -190,7 +197,11 @@ def discover_channels( rows, key=lambda r: (-int(r[1]), r[0].title is None, (r[0].title or "").lower()) ) except YouTubeError as exc: - log.warning("discovery: channel enrich failed (user %s): %s", user.id, exc) + log.warning( + "discovery: channel enrich failed: %s", + exc, + extra=logs.event("channels.discovery.enrich_failed", reason=exc.reason), + ) db.rollback() return [ @@ -298,7 +309,13 @@ def channel_detail( db.commit() channel = db.get(Channel, channel_id) except YouTubeError as exc: - log.warning("channel detail enrich failed (%s): %s", channel_id, exc) + log.warning( + "channel detail enrich failed: %s", + exc, + extra=logs.event( + "channels.detail.enrich_failed", channel_id=channel_id, reason=exc.reason + ), + ) db.rollback() sub = db.execute( select(Subscription).where( @@ -559,8 +576,11 @@ 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"). - msg = str(exc).lower() - if "already exists" in msg or "duplicate" in msg: + # On the reason code, never on the prose: the error no longer carries the body (it is + # the request quoted back), and a message YouTube rewords would silently turn "already + # following" back into a 422 the user cannot act on. `reason` is comma-joined when the + # body listed several. + if "subscriptionDuplicate" in exc.reason.split(","): yt_sub_id = "" else: raise HTTPException( @@ -574,7 +594,15 @@ def subscribe( try: apply_channel_details(db, yt.get_channels([channel_id])) except YouTubeError as exc: - log.warning("subscribe: stub enrich failed (%s): %s", channel_id, exc) + log.warning( + "subscribe: stub enrich failed: %s", + exc, + extra=logs.event( + "channels.subscribe.enrich_failed", + channel_id=channel_id, + reason=exc.reason, + ), + ) db.add( Subscription( user_id=user.id, diff --git a/backend/app/routes/downloads.py b/backend/app/routes/downloads.py index b128bc6e..3077f192 100644 --- a/backend/app/routes/downloads.py +++ b/backend/app/routes/downloads.py @@ -587,6 +587,8 @@ def _clean_url(raw) -> str | None: # authority. This one already has a "not a plausible URL" answer, so the typo belongs in it. try: parsed = urlparse(url) + # silent-ok: a typo in a link someone pasted. None is this function's "not a plausible URL" + # answer, the caller already has one, and any line here would carry the URL itself. except ValueError: return None if not parsed.netloc: diff --git a/backend/app/routes/feed.py b/backend/app/routes/feed.py index e037295b..9c2dac8d 100644 --- a/backend/app/routes/feed.py +++ b/backend/app/routes/feed.py @@ -256,6 +256,8 @@ def set_video_state( db.delete(row) try: db.commit() + # silent-ok: the documented lost race — a concurrent player checkpoint already removed + # or moved this row. The state the caller asked for is the state that holds either way. except StaleDataError: db.rollback() return {"video_id": video_id, "status": "new"} @@ -298,6 +300,7 @@ def clear_video_state( db.delete(row) try: db.commit() + # silent-ok: the row went under the delete, which is the outcome the delete wanted. except StaleDataError: db.rollback() return {"video_id": video_id, "status": "new", "position_seconds": 0} @@ -355,6 +358,7 @@ def set_video_progress( # have removed/updated this row already — tolerate the lost race. try: db.commit() + # silent-ok: exactly the race the comment above describes; the response stays true. except StaleDataError: db.rollback() return {"video_id": video_id, "position_seconds": 0} diff --git a/backend/app/routes/messages.py b/backend/app/routes/messages.py index c2c030a9..e9f705c6 100644 --- a/backend/app/routes/messages.py +++ b/backend/app/routes/messages.py @@ -449,6 +449,8 @@ async def messages_ws(ws: WebSocket) -> None: try: while True: await ws.receive_text() + # silent-ok: the ordinary way a chat socket ends — a closed tab. The `finally` below is the + # whole handling, and nothing failed. except WebSocketDisconnect: pass finally: diff --git a/backend/app/routes/plex/_shared.py b/backend/app/routes/plex/_shared.py index 2a193eab..02ec2fc3 100644 --- a/backend/app/routes/plex/_shared.py +++ b/backend/app/routes/plex/_shared.py @@ -1,14 +1,13 @@ """Shared helpers, serializers and constants for the plex route package.""" -import logging - from fastapi import HTTPException from sqlalchemy.orm import Session +from app import logs from app.models import PlexItem from app.plex.lookups import by_rating_key -log = logging.getLogger("siftlode.plex") +log = logs.get_logger(__name__) def item_or_404(db: Session, rating_key: str) -> PlexItem: diff --git a/backend/app/routes/plex/detail.py b/backend/app/routes/plex/detail.py index f2bcfc7e..8a52df0e 100644 --- a/backend/app/routes/plex/detail.py +++ b/backend/app/routes/plex/detail.py @@ -9,6 +9,7 @@ from fastapi import APIRouter, Depends, HTTPException from sqlalchemy import func, select from sqlalchemy.orm import Session +from app import logs from app.auth import current_user from app.db import get_db from app.models import ( @@ -30,6 +31,8 @@ from app.plex.lookups import by_rating_key from app.routes.plex._shared import _norm_lang, item_or_404 from app.routes.plex.collections import _collection_source +log = logs.get_logger(__name__) + router = APIRouter(prefix="/api/plex", tags=["plex"]) @@ -65,7 +68,21 @@ def _show_enrichment(db: Session, rating_key: str) -> tuple[dict, list]: related_f = ex.submit(plex.related, rating_key) # swallows its own errors → [] meta = meta_f.result() or {} related_raw = related_f.result() - except (PlexError, PlexNotConfigured): + except PlexNotConfigured: + # silent-ok: not a failure but a state — this instance has no Plex server, and the page + # is meant to render from the local rows alone. + return {}, [] + except PlexError as exc: + # The detail page still renders, from the rows the sync left behind: no cast, no related + # strip, no rich detail. Indistinguishable on screen from a show that simply has none. + log.warning( + "live Plex enrichment failed for a show", + extra=logs.event( + "plex.detail.show_enrich_failed", + rating_key=rating_key, + reason=type(exc).__name__, + ), + ) return {}, [] # Don't cache an EMPTY related list: plex.related() swallows a transient failure as [] (same as a # genuinely no-related show), so caching it would serve an empty "related" section for the whole TTL @@ -145,12 +162,26 @@ def show_detail( sh.people_enriched_at = datetime.now(timezone.utc) try: db.commit() - except Exception: + except Exception: # noqa: BLE001 — a failed enrich must not fail the page + # The rollback un-does the enrichment AND the `people_enriched_at` stamp, so the + # next view tries again — but if the commit keeps failing nobody ever hears, and + # the cast section stays empty for good. + log.warning( + "the show enrichment could not be committed", + extra=logs.event( + "plex.detail.enrich_commit_failed", rating_key=sh.rating_key, kind="show" + ), + ) db.rollback() - except Exception: + except Exception: # noqa: BLE001 — the local episode list must render whatever Plex does # Best-effort only — the local episode list is already assembled, so any live-Plex failure - # (not configured, HTTP/JSON shape) must degrade, not 500. - pass + # (not configured, HTTP/JSON shape) must degrade, not 500. With the traceback, because what + # is left in here after the Plex errors above are handled is our own shape bugs. + log.warning( + "the live part of a show page could not be built", + extra=logs.event("plex.detail.show_extras_failed", rating_key=sh.rating_key), + exc_info=True, + ) imdb_id = sh.imdb_id return { @@ -295,6 +326,14 @@ def _episode_nav(db: Session, it: PlexItem) -> tuple[str | None, str | None]: try: i = keys.index(it.rating_key) except ValueError: + # An episode missing from its own show's ordered list — the two came out of the same sync, + # so this is a gap in it. The page loses its previous/next arrows and says nothing. + log.info( + "an episode is not in its show's episode list; no previous/next", + extra=logs.event( + "plex.detail.episode_nav_missing", rating_key=it.rating_key, show_id=it.show_id + ), + ) return None, None return (keys[i - 1] if i > 0 else None), (keys[i + 1] if i < len(keys) - 1 else None) @@ -366,8 +405,32 @@ def item_detail( "text": codec not in subtitles.BITMAP_SUBS, } ) - except Exception: - pass # live extras (markers/streams) are best-effort; any live-Plex failure must degrade, not 500 — playback works without them + # Best-effort, but not free: what either branch drops is the subtitle stream list and the intro + # markers, so the player offers no subtitles and no skip button — and looks like a file that has + # neither. + except PlexNotConfigured: + # silent-ok: not a failure but a state — no Plex server, and nothing to play from anyway. + pass + except PlexError as exc: + log.warning( + "the live extras for an item could not be fetched", + extra=logs.event( + "plex.detail.extras_failed", + rating_key=it.rating_key, + kind=it.kind, + reason=type(exc).__name__, + ), + ) + except Exception: # noqa: BLE001 — playback works without the extras; never 500 here + # Plex answered and WE could not read it — a shape our parsing does not expect. The same + # split `show_detail` makes: the stack is the only thing that says where. + log.warning( + "the live extras for an item could not be read", + extra=logs.event( + "plex.detail.extras_unreadable", rating_key=it.rating_key, kind=it.kind + ), + exc_info=True, + ) # Lazy enrichment (movies only): the live fetch above carries the FULL cast + rich detail (the sync # only stored the listing's top ~3), so fill a not-yet-enriched movie — its cast becomes filterable @@ -380,7 +443,15 @@ def item_detail( it.people_enriched_at = datetime.now(timezone.utc) try: db.commit() - except Exception: + except Exception: # noqa: BLE001 — a failed enrich must not fail the page + # Same as the show path above: the info page then serves the three names the listing + # sync stored, and the full cast it just fetched is thrown away unreported. + log.warning( + "the movie enrichment could not be committed", + extra=logs.event( + "plex.detail.enrich_commit_failed", rating_key=it.rating_key, kind="movie" + ), + ) db.rollback() hu = lang == "hu" diff --git a/backend/app/routes/plex/people.py b/backend/app/routes/plex/people.py index ccef7c92..4b31922a 100644 --- a/backend/app/routes/plex/people.py +++ b/backend/app/routes/plex/people.py @@ -1,6 +1,5 @@ """Plex people: cast/crew filter-chip cards + a single person's filmography page.""" -import logging import threading import time @@ -8,6 +7,7 @@ from fastapi import APIRouter, BackgroundTasks, Depends from sqlalchemy import func, or_, select from sqlalchemy.orm import Session +from app import logs from app.auth import current_user from app.db import SessionLocal, get_db from app.models import ( @@ -22,7 +22,7 @@ from app.plex.cards import movie_card, show_card from app.plex.query import content_libs, split_csv router = APIRouter(prefix="/api/plex", tags=["plex"]) -log = logging.getLogger("siftlode.plex") +log = logs.get_logger(__name__) def _resolve_known_for( diff --git a/backend/app/routes/search.py b/backend/app/routes/search.py index 91ecad5d..f06adedf 100644 --- a/backend/app/routes/search.py +++ b/backend/app/routes/search.py @@ -13,7 +13,6 @@ this search-discovered "noise" by default. Shorts and currently-live/upcoming vi ingested this way (Shorts are confirmed by the youtube.com/shorts probe; live/upcoming are dropped from the search response up front).""" -import logging from concurrent.futures import ThreadPoolExecutor from datetime import datetime, timezone @@ -23,7 +22,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 ( @@ -45,8 +44,7 @@ from app.youtube import search_scrape from app.youtube.client import YouTubeClient, YouTubeError from app.youtube.shorts import make_client, probe_is_short -log = logging.getLogger("siftlode.search") - +log = logs.get_logger(__name__) router = APIRouter(prefix="/api/search", tags=["search"]) # search.list costs this many quota units per page. @@ -132,6 +130,13 @@ def _ingest_candidates( apply_channel_details(db, details) db.commit() except YouTubeError: + # The stubs remain and the details can be backfilled later — but until they are, those + # channels sit in the results with no thumbnail and no subscriber count, looking like + # channels that have neither. + log.warning( + "the channels found by a search could not be enriched", + extra=logs.event("search.channel_enrich_failed", channels=len(new_channel_ids)), + ) db.rollback() # details can be backfilled later; the stubs remain # 2) Video stubs, flagged via_search. Existing rows keep their flags (ON CONFLICT DO @@ -161,6 +166,12 @@ def _ingest_candidates( with quota.attribute(user.id, quota.QuotaAction.VIDEOS_ENRICH): detail_by_id = {it["id"]: it for it in yt.get_videos(ids)} except YouTubeError: + # Every candidate then stays unenriched, and an unenriched video cannot be judged live or + # Short — so it is dropped. A working search returns nothing and reads as "no results". + log.warning( + "the videos found by a search could not be enriched", + extra=logs.event("search.video_enrich_failed", candidates=len(ids)), + ) detail_by_id = {} enriched_at = datetime.now( timezone.utc @@ -238,12 +249,22 @@ def search_youtube( daily_limit = sysconfig.get_int(db, "search_daily_limit_per_user") used = quota.actions_today(db, user.id, quota.QuotaAction.VIDEOS_SEARCH) if used >= daily_limit: + # The 429 is in the request line either way; which of the two caps produced it is not, and + # they are answered by different things — this one by tomorrow, the other by the admin. + log.info( + "a live search was refused: the per-user daily cap is spent", + extra=logs.event("search.refused", reason="daily_cap", limit=daily_limit), + ) raise HTTPException( status_code=429, detail=f"You've reached today's YouTube search limit ({daily_limit}). Try again tomorrow.", ) # The 100-unit budget pre-check only applies to the API source. if source == "api" and not quota.can_spend(db, SEARCH_COST): + log.info( + "a live search was refused: the shared YouTube budget is spent", + extra=logs.event("search.refused", reason="shared_quota", cost=SEARCH_COST), + ) raise HTTPException( status_code=429, detail="The shared YouTube quota for today is used up. Try again tomorrow.", @@ -291,7 +312,29 @@ 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, and only + # under this user's own consent — not whenever the process runs at TRACE. + log.exception( + "live search ingest failed", + extra=logs.event( + "search.live.ingest_failed", + source=source, + candidates=len(candidates), + collected=len(collected), + ), + ) + if logs.consented_trace(): + log.log( + logs.TRACE, + "the term the ingest failed on", + # log-pii-ok: only under this user's own Teljes consent + extra=logs.event("search.live.term", term=term), + ) if collected: break # keep what earlier pages already gathered raise HTTPException( diff --git a/backend/app/scheduler.py b/backend/app/scheduler.py index 08683592..ec2e8309 100644 --- a/backend/app/scheduler.py +++ b/backend/app/scheduler.py @@ -2,7 +2,6 @@ recent-first / deep backfill. Runs inside the API process (single worker).""" import contextvars -import logging import threading from datetime import datetime, timezone from typing import Callable @@ -10,7 +9,7 @@ from typing import Callable from apscheduler.schedulers.background import BackgroundScheduler from sqlalchemy import select -from app import audit, logsink, progress, quota +from app import audit, logs, logsink, progress, quota from app.audit import AuditAction from app.config import settings from app.db import SessionLocal @@ -35,8 +34,7 @@ from app.sync.runner import ( run_subscription_resync, ) -logger = logging.getLogger("siftlode.scheduler") - +log = logs.get_logger(__name__) _scheduler: BackgroundScheduler | None = None # Per-job run activity, kept in-memory for the admin Scheduler dashboard to read (the @@ -104,7 +102,7 @@ def apply_interval(db, job_id: str, minutes: int) -> int: db.commit() if _scheduler is not None and _scheduler.get_job(job_id) is not None: _scheduler.reschedule_job(job_id, trigger="interval", minutes=minutes) - logger.info("rescheduled job %s to every %s min", job_id, minutes) + log.info("rescheduled job %s to every %s min", job_id, minutes) return minutes @@ -131,7 +129,7 @@ def _notify_done(db, actor_id: int, job_id: str, status: str, summary: str | Non ) except Exception: db.rollback() - logger.exception("failed to write completion notification for job %s", job_id) + log.exception("failed to write completion notification for job %s", job_id) def _run_changed(result) -> bool: @@ -167,7 +165,7 @@ def _audit_run(db, actor_id, job_id, status, summary, result) -> None: db.commit() except Exception: db.rollback() - logger.exception("failed to write audit row for job %s", job_id) + log.exception("failed to write audit row for job %s", job_id) def _job(name: str, fn) -> None: @@ -175,7 +173,7 @@ def _job(name: str, fn) -> None: # HERE, atomically: whichever reaches this first wins, the other skips. This is the real # single-run guard — trigger_job's pre-check is only a fast best-effort answer for the UI. if not _claim_running(name): - logger.info("job %s already running — skipping this trigger", name) + log.info("job %s already running — skipping this trigger", name) return db = SessionLocal() actor_id = _manual_actor.get() # set only for a manual "run now" trigger @@ -188,7 +186,7 @@ def _job(name: str, fn) -> None: try: if is_sync_paused(db): - logger.info("job %s skipped (sync paused)", name) + log.info("job %s skipped (sync paused)", name) _record( name, status="skipped", @@ -203,14 +201,14 @@ def _job(name: str, fn) -> None: with progress.bind(sink): result = fn(db) summary = _summarize(result) - logger.info("job %s -> %s", name, result) + log.info("job %s -> %s", name, result) _record(name, status="ok", last_finished=_now_iso(), last_result=summary, progress=None) if actor_id is not None: _notify_done(db, actor_id, name, "ok", summary) _audit_run(db, actor_id, name, "ok", summary, result) except Exception as exc: db.rollback() - logger.exception("job %s failed", name) + log.exception("job %s failed", name) err = str(exc) or exc.__class__.__name__ _record(name, status="error", last_finished=_now_iso(), last_error=err, progress=None) if actor_id is not None: @@ -493,7 +491,7 @@ def start_scheduler() -> None: scheduler.add_job(fn, "interval", minutes=iv[job_id], id=job_id) scheduler.start() _scheduler = scheduler - logger.info("scheduler started") + log.info("scheduler started") def shutdown_scheduler() -> None: diff --git a/backend/app/security.py b/backend/app/security.py index 1f4ca4f1..8e7f68d3 100644 --- a/backend/app/security.py +++ b/backend/app/security.py @@ -1,10 +1,14 @@ import hashlib from argon2 import PasswordHasher +from argon2.exceptions import VerifyMismatchError from cryptography.fernet import Fernet +from app import logs from app.config import settings +log = logs.get_logger(__name__) + # argon2id with the library defaults (sensible memory/time cost). One shared hasher instance. _ph = PasswordHasher() @@ -24,8 +28,16 @@ def verify_password(password: str, hashed: str | None) -> bool: return False try: return _ph.verify(hashed, password) - except Exception: - # Any failure (mismatch, malformed hash) is a non-match — never raise to the caller. + except VerifyMismatchError: + return False # silent-ok: a wrong password. The commonest path through this function. + except Exception as exc: # noqa: BLE001 — never raise to the caller, whatever went wrong + # Everything else is a hash this process cannot USE — truncated in the column, written by + # a different argon2 build. It is answered as "wrong password", so the owner of that + # account is locked out by a bug and told they mistyped. + log.warning( + "a stored password hash could not be verified", + extra=logs.event("auth.password.hash_unusable", reason=type(exc).__name__), + ) return False @@ -60,5 +72,13 @@ def decrypt_optional(value: str | None) -> str | None: return None try: return _require_fernet().decrypt(value.encode()).decode() - except Exception: + except Exception as exc: # noqa: BLE001 — callers fall back to a refresh, never to an error + # Info rather than warning because the docstring's legacy-plaintext case comes through + # here too and is harmless. What is NOT harmless looks identical: a rotated + # TOKEN_ENCRYPTION_KEY turns every stored token unreadable at once, and every account + # then reads as "not connected" with nothing saying the key is the reason. + log.info( + "a stored ciphertext could not be decrypted", + extra=logs.event("security.decrypt.failed", reason=type(exc).__name__), + ) return None diff --git a/backend/app/state.py b/backend/app/state.py index 59693dc7..4754bf0a 100644 --- a/backend/app/state.py +++ b/backend/app/state.py @@ -1,15 +1,14 @@ """Global admin-controlled app state (e.g. pausing background sync, first-run setup).""" -import logging import secrets from sqlalchemy.orm import Session +from app import logs from app.models import AppState from app.security import hash_token -log = logging.getLogger("siftlode.state") - +log = logs.get_logger(__name__) # Once configuration completes in this process it never reverts, so cache it to skip the per-request # DB hit in the setup-mode gate (see main.setup_gate). Starts False; refreshed from the DB. _configured_cache = False diff --git a/backend/app/sync/autotag.py b/backend/app/sync/autotag.py index 57e36ab1..471bebf7 100644 --- a/backend/app/sync/autotag.py +++ b/backend/app/sync/autotag.py @@ -6,17 +6,16 @@ topicDetails categories and the channel's dominant video category. System tags a regenerated freely; user tags are never touched here. """ -import logging import re from sqlalchemy import and_, exists, func, select from sqlalchemy.orm import Session -log = logging.getLogger("siftlode.autotag") - -from app import progress, sysconfig +from app import logs, progress, sysconfig from app.models import Channel, ChannelTag, Tag, Video +log = logs.get_logger(__name__) + # --- language id (offline, deterministic, small) --- try: from py3langid.langid import MODEL_FILE, LanguageIdentifier @@ -29,7 +28,13 @@ try: def _restrict(codes: list[str]) -> None: _identifier.set_languages(codes) -except Exception: # pragma: no cover - fallback to module-level API +except Exception: # noqa: BLE001 — pragma: no cover, fallback to the module-level API + # The fallback classifies without the normalisation the identifier applies, so language tags + # come out subtly different — and nothing else in the app would ever hint at which path ran. + log.info( + "the langid model could not be loaded; using the module-level classifier", + extra=logs.event("autotag.langid.fallback"), + ) import py3langid as _langid def _classify(text: str): diff --git a/backend/app/sync/explore.py b/backend/app/sync/explore.py index e89feb42..75b2aa45 100644 --- a/backend/app/sync/explore.py +++ b/backend/app/sync/explore.py @@ -8,13 +8,12 @@ stay private to users who explored (or subscribe to) the channel — the feed qu otherwise the cleanup job hard-deletes the channel and its untouched ephemeral videos after a grace period (mirrors the maintenance job's grace-then-delete safety).""" -import logging from datetime import timedelta from sqlalchemy import delete, or_, select from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.models import ( Channel, ExploredChannel, @@ -28,7 +27,7 @@ from app.sync.videos import insert_stubs, stub_from_playlist_item, apply_video_d from app.utils import now_utc as _now from app.youtube.client import YouTubeClient -log = logging.getLogger("siftlode.explore") +log = logs.get_logger(__name__) def followed_channel(): diff --git a/backend/app/sync/maintenance.py b/backend/app/sync/maintenance.py index 8b4584ef..680a63cc 100644 --- a/backend/app/sync/maintenance.py +++ b/backend/app/sync/maintenance.py @@ -20,13 +20,12 @@ Quota: phase 1 costs ~(flagged / 50) units, phase 2 ~(batch / 50). Both respect backfill reserve as the other jobs so interactive syncs never starve. """ -import logging from datetime import timedelta from sqlalchemy import select from sqlalchemy.orm import Session -from app import progress, quota, sysconfig +from app import logs, progress, quota, sysconfig from app.config import settings from app.models import Playlist, PlaylistItem, Video from app.notifications import create_notification @@ -35,8 +34,7 @@ from app.sync.videos import apply_video_details, parse_dt from app.utils import now_utc as _now from app.youtube.client import YouTubeClient -log = logging.getLogger("siftlode.maintenance") - +log = logs.get_logger(__name__) # Reasons recorded on Video.unavailable_reason. "removed" = absent from videos.list # (deleted or made private); "abandoned" = an upcoming premiere that never went live. GRACE_DAYS_BY_REASON = { diff --git a/backend/app/sync/playlists.py b/backend/app/sync/playlists.py index d3201b39..056c7a9d 100644 --- a/backend/app/sync/playlists.py +++ b/backend/app/sync/playlists.py @@ -8,7 +8,6 @@ ingested (with a stub channel) so the mirror is faithful.""" import hashlib import json -import logging from collections.abc import Callable from dataclasses import dataclass from datetime import datetime, timezone @@ -17,15 +16,14 @@ from typing import TypeVar from sqlalchemy import delete, select from sqlalchemy.orm import Session -from app import progress, quota +from app import logs, progress, quota from app.auth import has_read_scope from app.models import Channel, Playlist, PlaylistItem, User, Video from app.sync.runner import token_users from app.sync.videos import apply_video_details, parse_dt from app.youtube.client import YouTubeClient, YouTubeError -log = logging.getLogger("siftlode.sync") - +log = logs.get_logger(__name__) # Cost of a single YouTube write op (playlists/playlistItems insert/update/delete). WRITE_UNIT_COST = 50 @@ -59,7 +57,17 @@ def _load_baseline(pl: Playlist) -> tuple[list[str] | None, set[str]]: return None, set() try: val = json.loads(pl.synced_video_ids) - except (ValueError, TypeError): + except (ValueError, TypeError) as exc: + # No baseline means the three-way merge has no "what we last agreed on" to subtract, so + # it degrades to a union: nothing is lost, but a delete made on either side comes back. + log.warning( + "the sync baseline for a playlist could not be read; merging as a union", + extra=logs.event( + "sync.playlist.baseline_unreadable", + playlist_id=pl.id, + reason=type(exc).__name__, + ), + ) return None, set() if isinstance(val, list): return [str(v) for v in val], set() @@ -410,8 +418,11 @@ class _Breaker: write site can't accidentally implement two thirds of the protocol (forgetting to record a failure would silently disable the breaker for that operation).""" - def __init__(self, limit: int = _MAX_CONSECUTIVE_FAILURES) -> None: + def __init__( + self, limit: int = _MAX_CONSECUTIVE_FAILURES, playlist_id: int | None = None + ) -> None: self.limit = limit + self.playlist_id = playlist_id # for the failure line only self.streak = 0 self.tripped = False @@ -432,7 +443,9 @@ class _Breaker: self.limit, ) - def run(self, op: Callable[[], T], on_fail: Callable[[], None]) -> T | _Failed: + def run( + self, op: Callable[[], T], on_fail: Callable[[], None], action: str = "write" + ) -> T | _Failed: """Attempt one YouTube write. Returns the op's result, or `FAILED` when the breaker is already tripped (op not called) or the op raised YouTubeError. `on_fail` records the item in the caller's failure list either way.""" @@ -441,7 +454,19 @@ class _Breaker: return FAILED try: out = op() - except YouTubeError: + except YouTubeError as exc: + # The client logged the call, but not which playlist it was for or what kind of write + # — and the caller's failure list only ever reaches the user as a count. Not the video: + # what is in someone's playlist is a row of their history, the same as a download. + log.debug( + "a playlist write to YouTube failed", + extra=logs.event( + "sync.playlist.item_push_failed", + playlist_id=self.playlist_id, + action=action, + reason=exc.reason, + ), + ) on_fail() self.hit(False) return FAILED @@ -460,7 +485,7 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: local = _local_video_ids(db, pl) inserted = deleted = reordered = created = pulled = removed_local = 0 failures: list[str] = [] - breaker = _Breaker() + breaker = _Breaker(playlist_id=pl.id) with YouTubeClient(db, user) as yt: if not pl.yt_playlist_id: pl.yt_playlist_id = yt.create_playlist(pl.name) @@ -471,6 +496,7 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: added = breaker.run( lambda v=vid: yt.add_playlist_item(pl.yt_playlist_id, v), lambda v=vid: failures.append(v), + "add", ) if not isinstance(added, _Failed): inserted += 1 @@ -533,7 +559,17 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: if snippet is not None and (snippet.get("title") or "") != pl.name: try: yt.update_playlist_title(pl.yt_playlist_id, pl.name) - except YouTubeError: + except YouTubeError as exc: + # All the caller passes on is the word "title", which says the rename did not + # happen but not that YouTube refused it, or why. + log.debug( + "a playlist rename did not reach YouTube", + extra=logs.event( + "sync.playlist.title_push_failed", + playlist_id=pl.id, + reason=exc.reason, + ), + ) failures.append("title") # Propagate genuine local deletes. for vid in mp.remove_from_yt: @@ -543,6 +579,7 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: dropped = breaker.run( lambda i=item_id: yt.delete_playlist_item(i), lambda v=vid: failures.append(v), + "delete", ) if not isinstance(dropped, _Failed): deleted += 1 @@ -552,6 +589,7 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: item_id = breaker.run( lambda v=vid: yt.add_playlist_item(pl.yt_playlist_id, v), lambda v=vid: failures.append(v), + "add", ) if not isinstance(item_id, _Failed): item_id_by_vid[vid] = item_id @@ -571,6 +609,7 @@ def merge_playlist(db: Session, user: User, pl: Playlist, *, live=None) -> dict: item_id_by_vid[w], pl.yt_playlist_id, w, pos ), lambda w=want: failures.append(w), + "move", ) if isinstance(moved, _Failed): continue diff --git a/backend/app/sync/runner.py b/backend/app/sync/runner.py index 948c92f5..7220620c 100644 --- a/backend/app/sync/runner.py +++ b/backend/app/sync/runner.py @@ -15,7 +15,7 @@ from sqlalchemy.orm import Session from app import logs, progress, quota, sysconfig -log = logging.getLogger("siftlode.sync") +log = logs.get_logger(__name__) from app.db import SessionLocal from app.models import Channel, OAuthToken, Subscription, User from app.sync.explore import followed_channel @@ -120,14 +120,18 @@ def run_rss_poll(db: Session, channels: list[Channel] | None = None) -> dict[str except RssError as exc: log.debug("RSS poll skipped for channel %s: %s", channel.id, exc) fail(exc.reason, f"{channel.id}: {exc}") - except Exception as exc: + # silent-ok: `fail(unexpected=…)` is the report — it logs at ERROR with the + # traceback, once per reason per poll, which is the flood control this loop needs. + except Exception as exc: # noqa: BLE001 — one channel must not stop the poll fail( "error", f"{channel.id}: {exc}", unexpected=f"RSS fetch failed for {channel.id}" ) else: try: new += apply_rss_feed(db, channel, entries) - except Exception as exc: + # silent-ok: `fail(unexpected=…)` below is the report — ERROR with the traceback, + # once per reason per poll. + except Exception as exc: # noqa: BLE001 — one channel must not stop the poll # A write failure (read-only DB, failover) leaves the channel just as un-polled # as an unreachable feed — count it, or a wholly broken run reports "failed=0". db.rollback() diff --git a/backend/app/sync/subscriptions.py b/backend/app/sync/subscriptions.py index b37858df..bf964093 100644 --- a/backend/app/sync/subscriptions.py +++ b/backend/app/sync/subscriptions.py @@ -1,21 +1,23 @@ """Import the authenticated user's YouTube subscriptions and channel metadata.""" -import logging from datetime import datetime, timezone from sqlalchemy import select from sqlalchemy.orm import Session +from app import logs from app.models import Channel, Subscription, User from app.utils import normalize_description from app.youtube.client import YouTubeClient, best_thumbnail -log = logging.getLogger("siftlode.sync") +log = logs.get_logger(__name__) def _to_int(value) -> int | None: try: return int(value) if value is not None else None + # silent-ok: an upstream count we cannot read is stored as no count, which the card renders as + # absent rather than as zero. Per-channel over a whole subscription list, so it must stay quiet. except (TypeError, ValueError): return None @@ -25,6 +27,8 @@ def _parse_dt(value: str | None) -> datetime | None: return None try: return datetime.fromisoformat(value.replace("Z", "+00:00")) + # silent-ok: as `_to_int` above — an unreadable upstream date becomes NULL, and every caller + # already treats a missing date as unknown. except ValueError: return None diff --git a/backend/app/sync/videos.py b/backend/app/sync/videos.py index 94fc230d..a257c92a 100644 --- a/backend/app/sync/videos.py +++ b/backend/app/sync/videos.py @@ -39,6 +39,8 @@ def parse_dt(value: str | None) -> datetime | None: return None try: return datetime.fromisoformat(value.replace("Z", "+00:00")) + # silent-ok: a pure parser with no video to name — the only thing it could put in a line is + # the upstream string itself. None is stored, and absent is how the UI renders it. except ValueError: return None diff --git a/backend/app/sysconfig.py b/backend/app/sysconfig.py index 016080be..8b2f49b3 100644 --- a/backend/app/sysconfig.py +++ b/backend/app/sysconfig.py @@ -8,20 +8,22 @@ stored Fernet-encrypted at rest (requires TOKEN_ENCRYPTION_KEY; without it, secr stored in the DB and stay env-only). """ -import logging from dataclasses import dataclass from sqlalchemy.orm import Session -from app import security +from app import logs, security from app.config import Settings, canonical_choice, choices_of, settings from app.models import SystemConfig -log = logging.getLogger("siftlode.config") - +log = logs.get_logger(__name__) # Config keys whose stored ciphertext failed to decrypt — tracked so the warning is logged once per # key, not once per request (bounded by the number of secret config keys). _decrypt_warned: set[str] = set() +# The same for a stored value that no longer coerces (a choice list that shrank in a release): it +# fails on EVERY read of a hot knob until someone saves it again. Keyed with the value, so saving a +# different bad value is reported afresh (bounded by the keys times the values ever saved). +_coerce_warned: set[tuple[str, str]] = set() @dataclass(frozen=True) @@ -269,7 +271,17 @@ def get(db: Session, key: str): return _default(s) try: return _coerce(s, raw) - except (TypeError, ValueError): + except (TypeError, ValueError) as exc: + # The admin set this in the UI and it is quietly not in force: the app runs on the env + # default while the settings page goes on showing the value that was saved. + if (s.key, raw) not in _coerce_warned: + _coerce_warned.add((s.key, raw)) + log.warning( + "a stored setting could not be coerced; the default is used instead", + extra=logs.event( + "sysconfig.override_uncoercible", key=s.key, reason=type(exc).__name__ + ), + ) return _default(s) diff --git a/backend/app/worker.py b/backend/app/worker.py index 60e2c2fc..1aac2d5a 100644 --- a/backend/app/worker.py +++ b/backend/app/worker.py @@ -16,7 +16,6 @@ Design: * Crash-safe: on startup, orphaned `running` jobs are requeued and `downloading` assets reset. """ -import logging import os import shutil import signal @@ -24,6 +23,7 @@ import subprocess import sys import threading import time +from collections.abc import Callable from datetime import datetime, timezone from sqlalchemy import text @@ -45,8 +45,7 @@ from app.downloads.jobdb import ( from app.downloads.status import STOPPED_BY_ROUTE, JobStatus from app.models import DownloadJob, MediaAsset -log = logging.getLogger("siftlode.worker") - +log = logs.get_logger(__name__) _stop = threading.Event() @@ -73,13 +72,14 @@ def _wait_for_schema(timeout: float = 300.0) -> bool: with SessionLocal() as db: db.execute(text("SELECT 1 FROM download_jobs LIMIT 1")) return True - except Exception as exc: # noqa: BLE001 — table not migrated yet / DB not up yet + except Exception: # noqa: BLE001 — table not migrated yet / DB not up yet if time.monotonic() > deadline: - log.error( - "download schema still absent after %ss — the API's migrations have not landed; " - "exiting so the container restarts: %s", + # The traceback, not `str(exc)[:120]`: this is the last thing the worker says + # before it exits, and which driver call failed is the whole question. + log.exception( + "download schema still absent after %ss — the API's migrations have not " + "landed; exiting so the container restarts", timeout, - str(exc)[:120], ) return False log.info("waiting for the database schema (API migrations)…") @@ -219,8 +219,17 @@ def _signal_group(proc: subprocess.Popen, pgid: int | None, sig: int) -> None: os.killpg(pgid, sig) else: proc.send_signal(sig) - except (ProcessLookupError, OSError): - pass + except ProcessLookupError: + pass # silent-ok: the child already exited — the race this function is written around + except OSError as exc: + # Any OTHER refusal means the signal did not land and the child is still running, which + # is how a "cancelled" download keeps writing to a staging tree nobody is watching. + log.info( + "a download child could not be signalled", + extra=logs.event( + "download.child.signal_failed", signal=int(sig), reason=type(exc).__name__ + ), + ) def _stop_child(proc: subprocess.Popen, grace_s: float) -> None: @@ -230,6 +239,8 @@ def _stop_child(proc: subprocess.Popen, grace_s: float) -> None: child already exited, and `getpgid` yields None for a reaped pid, so no separate poll guard.""" try: pgid: int | None = os.getpgid(proc.pid) + # silent-ok: `getpgid` refuses for a reaped pid, which the docstring above already treats as + # the ordinary case — the escalation then signals the child alone and no-ops if it is gone. except OSError: pgid = None editmod.escalate_kill( @@ -250,23 +261,42 @@ def _stop_and_free(job_id: int, asset_id: int, proc: subprocess.Popen, grace_s: def _fail_after_kill( - job_id: int, asset_id: int, proc: subprocess.Popen, grace_s: float, error: str, error_code: str -) -> None: + job_id: int, + asset_id: int, + proc: subprocess.Popen, + grace_s: float, + error: str, + error_code: str, + cause: str | None = None, +) -> bool: """`_stop_and_free` + mark the job errored — for the watchdog's stall/timeout kills and the - supervisor-error fallback.""" + supervisor-error fallback. Returns whether the job failed here (`_fail_running`).""" _stop_and_free(job_id, asset_id, proc, grace_s) - _fail_running(job_id, error=error, error_code=error_code) + return _fail_running(job_id, error=error, error_code=error_code, cause=cause) def _fail_running( - job_id: int, *, error: str, error_code: str | None, error_detail: str | None = None -) -> None: + job_id: int, + *, + error: str, + error_code: str | None, + error_detail: str | None = None, + cause: str | None = None, + exit_code: int | None = None, +) -> bool: """Fail a claimed job — only while it is still `running` (`service.finalize_if_running`), so a cancel/pause a route landed first is never turned back into `error`, which holds the asset the route already released. `error_detail` is written every time: a failure never shows an earlier - failure's explanation.""" + failure's explanation. + + `cause` is the worker's half of `download.job.failed`: the failures the child never got to + report because it was killed, never ran or died — a stall, the wall-clock cap, a non-zero exit + (with its `exit_code`). Without it those left no line at all. A caller that logs its own line + (a worker error, with its stack — `_report_worker_error`) passes none and uses the returned + verdict. Logged only when the job actually failed here: a route's cancel that landed first is + not a failure. Returns whether it failed here.""" with SessionLocal() as db: - service.finalize_if_running( + failed = service.finalize_if_running( db, job_id, status=JobStatus.ERROR, @@ -276,6 +306,49 @@ def _fail_running( phase=None, ) db.commit() + if cause is not None and failed: + log.warning( + "job %s failed in the worker: %s", + job_id, + cause, + extra=logs.event( + "download.job.failed", + job_id=job_id, + error_code=error_code, + cause=cause, + **({"exit_code": exit_code} if exit_code is not None else {}), + ), + ) + return failed + + +def _report_worker_error(job_id: int, exc: Exception, cause: str, fail: Callable[[], bool]) -> None: + """A worker error on a job (the supervisor loop, or processing the job, raised): fail the job, + then ONE line with the stack. Its event says what the error did to the job — + `download.job.failed` when the job failed with it, `download.worker.error` when a route had + already stopped it (a cancel that landed first is not a failure, `_fail_running`). + + The line goes out even when failing the job raises (the database is down): as + `download.worker.error`, since the job was not failed, and the raise goes on to the caller — + without `exc` as its context, which this line has already carried with its stack.""" + failed = False + try: + failed = fail() + except BaseException as write_error: + write_error.__suppress_context__ = True + raise + finally: + log.error( + "job %s: worker error (%s)", + job_id, + cause, + exc_info=exc, + extra=logs.event( + "download.job.failed" if failed else "download.worker.error", + job_id=job_id, + cause=cause, + ), + ) def _run_supervised(job_id: int, asset_id: int) -> None: @@ -306,6 +379,8 @@ def _run_supervised(job_id: int, asset_id: int) -> None: try: proc.wait(timeout=poll_s) break # child finished on its own + # silent-ok: the timeout is the loop's clock, not a failure — it is what gives this + # thread a turn to check whether a route cancelled the job. except subprocess.TimeoutExpired: pass status, stale = _job_liveness(job_id) @@ -328,15 +403,20 @@ def _run_supervised(job_id: int, asset_id: int) -> None: # else: a terminal status under the cap (done/error, or a re-queued contended asset) means # the child is exiting on its own — keep polling; NEVER kill a finishing child (that could # drop its completion notice). - except Exception: # noqa: BLE001 — a watchdog error must NEVER leave the child running unsupervised - log.exception("supervisor loop failed for job %s; stopping the child", job_id) - _fail_after_kill( + except Exception as exc: # noqa: BLE001 — a watchdog error must NEVER leave the child running unsupervised + # silent-ok: not silent — `_report_worker_error` is the report. + _report_worker_error( job_id, - asset_id, - proc, - grace_s, - "The download was stopped after a worker error.", - "unknown", + exc, + "supervisor_error", + lambda: _fail_after_kill( + job_id, + asset_id, + proc, + grace_s, + "The download was stopped after a worker error.", + "unknown", + ), ) return @@ -355,9 +435,8 @@ def _run_supervised(job_id: int, asset_id: int) -> None: job_id, error=f"The download process exited unexpectedly (code {proc.returncode}).", error_code="unknown", - ) - log.warning( - "job %s: child exited %s without finishing", job_id, proc.returncode + cause="child_exit", + exit_code=proc.returncode, ) except Exception: # noqa: BLE001 — boot recovery is the backstop for a stuck 'running' job log.exception("post-exit reconciliation failed for job %s", job_id) @@ -371,6 +450,7 @@ def _run_supervised(job_id: int, asset_id: int) -> None: grace_s, f"The download stalled (no progress for {int(stall_s)}s) and was stopped.", "network", + cause="stalled", ) return if reason == "timeout": @@ -381,6 +461,7 @@ def _run_supervised(job_id: int, asset_id: int) -> None: grace_s, f"The download exceeded the {int(wall_s)}s time limit and was stopped.", "network", + cause="timeout", ) return # cancelled / abandon / shutdown: stop + free the asset, but leave the job's own DB status. @@ -389,10 +470,19 @@ def _run_supervised(job_id: int, asset_id: int) -> None: _requeue_if_running(job_id, None) # resume on the next boot elif reason == "abandon": log.warning( - "job %s: killed a child wedged past the wall-clock; DB status left intact", job_id + "job %s: killed a child wedged past the wall-clock; DB status left intact", + job_id, + extra=logs.event("download.child.abandoned", job_id=job_id), ) else: # cancelled - log.info("job %s: child stopped (route pause/cancel)", job_id) + # Not `download.job.aborted`: that is the child's line, logged when it notices the pause + # itself — and it often has, and is only tearing down when this poll comes round. This one + # says the worker had to stop it. + log.info( + "job %s: child stopped (route pause/cancel)", + job_id, + extra=logs.event("download.child.stopped", job_id=job_id), + ) def _cleanup_staging(asset_id: int) -> None: @@ -432,7 +522,7 @@ def _process_job(job_id: int) -> None: del cookie # only whether there is one matters here if asset is None: - _fail_running(job_id, error="No media asset", error_code=None) + _fail_running(job_id, error="No media asset", error_code=None, cause="no_asset") return if asset_status == "ready": @@ -444,6 +534,7 @@ def _process_job(job_id: int) -> None: error=asset_error or "Download failed", error_code=diagnosis.code, error_detail=diagnosis.detail, + cause="asset_failed", ) return if asset_status == "downloading": @@ -500,9 +591,23 @@ def _worker_loop(idx: int) -> None: with logs.bind(job_id=job_id): try: _process_job(job_id) - except Exception: # noqa: BLE001 - log.exception("processing job %s crashed", job_id) - _fail_running(job_id, error="Worker error", error_code=None) + except Exception as exc: # noqa: BLE001 + try: + _report_worker_error( + job_id, + exc, + "crash", + lambda: _fail_running(job_id, error="Worker error", error_code=None), + ) + # silent-ok: not silent — `_report_worker_error` logged the crash before this + # re-raise. Failing the job hit the database, and letting that out would end this + # worker thread for good; boot recovery settles a job left `running`. + except Exception: # noqa: BLE001 + log.exception( + "could not fail job %s after its crash", + job_id, + extra=logs.event("download.worker.fail_write_failed", job_id=job_id), + ) def main() -> None: diff --git a/backend/app/youtube/client.py b/backend/app/youtube/client.py index 2797c7e8..260aff31 100644 --- a/backend/app/youtube/client.py +++ b/backend/app/youtube/client.py @@ -6,24 +6,81 @@ so they don't depend on a specific user's token; subscriptions.list?mine=true al uses OAuth. """ -import logging from collections.abc import Iterator 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 -log = logging.getLogger("siftlode.youtube") - +log = logs.get_logger(__name__) GOOGLE_TOKEN_URL = "https://oauth2.googleapis.com/token" 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: + error = resp.json().get("error") + # The OAuth token endpoint's shape: `{"error": "invalid_grant", "error_description": …}`. + if isinstance(error, str): + return error or "<none>" + errors = (error or {}).get("errors") or [] + reasons = ",".join(e.get("reason", "") for e in errors if e.get("reason")) + # silent-ok: the sentinel it returns goes straight into the caller's warning line, which + # is the report. (Any non-JSON body — an HTML error page from a proxy.) + except Exception: # noqa: BLE001 + 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 YouTube response that is + not a success goes through here — the Data API's reads, writes and deletes and the OAuth + token refresh — so what may appear in a log line cannot drift apart between them, 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. (A request that got no + response at all is `_send`'s, with the reason `transport`.) The body is logged only under + the requesting user's own Teljes consent: it is the request quoted back.""" + 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, + ), + ) + if logs.consented_trace(): + log.log( + logs.TRACE, + "the upstream body behind it", + # log-pii-ok: only under this user's own Teljes consent, which 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,13 +119,13 @@ 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: raise YouTubeError( - f"YouTube API unreachable ({exc.__class__.__name__}: {exc})" + f"YouTube API unreachable ({exc.__class__.__name__}: {exc})", reason="transport" ) from exc # --- auth --- @@ -99,7 +156,7 @@ class YouTubeClient: }, ) if resp.status_code != 200: - raise YouTubeError(f"Token refresh failed: {resp.status_code} {resp.text[:200]}") + raise _upstream_failure("POST", "oauth2/token", resp) data = resp.json() access = data["access_token"] tok.access_token = encrypt(access) @@ -121,8 +178,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 +303,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 +333,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/app/youtube/search_scrape.py b/backend/app/youtube/search_scrape.py index 283a84d0..cfdbc95e 100644 --- a/backend/app/youtube/search_scrape.py +++ b/backend/app/youtube/search_scrape.py @@ -21,6 +21,10 @@ import re import httpx +from app import logs + +log = logs.get_logger(__name__) + _SEARCH_URL = "https://www.youtube.com/youtubei/v1/search" _RESULTS_URL = "https://www.youtube.com/results" # Public WEB InnerTube key + a recent client version. These are also embedded in every results @@ -74,7 +78,14 @@ def _get_config(client: httpx.Client) -> tuple[str, str]: key.group(1) if key else _FALLBACK_KEY, ver.group(1) if ver else _FALLBACK_CLIENT_VERSION, ) - except httpx.HTTPError: + except httpx.HTTPError as exc: + # The fallback pair is CACHED in `_config` for the life of the process, so one failed + # fetch at the wrong moment pins every later search to a hard-coded key and version — + # and when those go stale, search returns nothing at all, with no error anywhere. + log.warning( + "the InnerTube config could not be fetched; falling back to the pinned key", + extra=logs.event("youtube.scrape.config_fallback", reason=type(exc).__name__), + ) _config = (_FALLBACK_KEY, _FALLBACK_CLIENT_VERSION) return _config diff --git a/backend/app/youtube/shorts.py b/backend/app/youtube/shorts.py index 70c014d8..a3ed9e3e 100644 --- a/backend/app/youtube/shorts.py +++ b/backend/app/youtube/shorts.py @@ -18,6 +18,8 @@ def probe_is_short(client: httpx.Client, video_id: str) -> bool | None: """True if a Short, False if a regular video, None if undetermined (retry later).""" try: resp = client.get(SHORTS_URL.format(video_id=video_id), follow_redirects=False) + # silent-ok: None is the documented third state — "undetermined, ask again later" — and the + # scheduler retries it. It is not the same answer as False, so nothing is being hidden. except httpx.HTTPError: return None if resp.status_code == 200: diff --git a/backend/ruff.toml b/backend/ruff.toml index a3e03c0c..9bb4cdf0 100644 --- a/backend/ruff.toml +++ b/backend/ruff.toml @@ -9,4 +9,21 @@ line-length = 100 [lint] +# Beyond the default set, the rules that hold a LOG LINE to what E22.5 makes of it: +# LOG — stdlib logging misuse (`.warn()`, a logger built by hand, `exc_info` on `.exception`) +# G — the call's shape: %-style args, never an f-string the level filter cannot skip, and +# never `str(exc)` where `exc_info` would carry the traceback +# T20 — `print` instead of a log line. Two deliberate ones remain, each with its `# noqa` +# and a why: `downloads/runner.py`'s usage line is for whoever typed it, and +# `logsink.py` reports the SINK's own failure, which cannot be logged into the sink. +# TRY400 — `.error()` in an `except` where `.exception()` would keep the traceback +# TRY401 — the exception spelled into the message AND passed as `exc_info` (it is in both) +# S112 — `except: continue`, the silent swallow inside a loop +# S110 — `except: pass`, the same thing outside one +# BLE001 — a blind `except Exception`. Every one that remains carries `# noqa: BLE001 — <why>`, +# which is the point: catching everything is sometimes right (a worker thread with +# nobody to raise to, a best-effort backfill inside a sync) and always worth a sentence. +# The wider rule these two enforce lives in tests/test_swallowed_exceptions.py: a handler that +# neither logs nor re-raises says `# silent-ok: <why>`. Ruff sees only the two narrow shapes. +extend-select = ["LOG", "G", "T20", "TRY400", "TRY401", "S110", "S112", "BLE001"] ignore = ["E402"] diff --git a/backend/tests/conftest.py b/backend/tests/conftest.py index 4472445b..9bec2f5e 100644 --- a/backend/tests/conftest.py +++ b/backend/tests/conftest.py @@ -49,7 +49,9 @@ def _db_reachable() -> bool: with probe.connect() as conn: conn.execute(text("SELECT 1")) return True - except Exception: + # silent-ok / noqa BLE001: the question is literally "can anything reach it", so every + # failure is the same answer — and this runs at import, before logging is configured. + except Exception: # noqa: BLE001 return False finally: probe.dispose() diff --git a/backend/tests/test_channel_subscribe_upstream.py b/backend/tests/test_channel_subscribe_upstream.py new file mode 100644 index 00000000..a7f6331d --- /dev/null +++ b/backend/tests/test_channel_subscribe_upstream.py @@ -0,0 +1,69 @@ +"""Subscribing when YouTube says no — and when "no" means "you already are". + +The error no longer carries YouTube's body (it is the request quoted back, and it went into a log +line and a 422), so "already following" is recognised by the reason code and nothing else. +DB lane. +""" + +import pytest +from fastapi import HTTPException +from sqlalchemy import select + +from app.models import Channel, Subscription +from app.routes import channels +from app.youtube.client import YouTubeError + + +def _youtube_refusing(reason: str): + class _Client: + def __init__(self, db, user): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def insert_subscription(self, channel_id): + raise YouTubeError(f"POST subscriptions -> 400: {reason}", reason=reason) + + def get_channels(self, ids): + return [] + + return _Client + + +@pytest.fixture +def stub_channel(db): + db.add(Channel(id="UCdup", title="Already followed")) + db.commit() + return "UCdup" + + +@pytest.mark.parametrize("reason", ["subscriptionDuplicate", "quotaExceeded,subscriptionDuplicate"]) +def test_already_following_on_youtube_is_recorded_not_refused( + db, make_user, monkeypatch, stub_channel, reason +): + user = make_user() + monkeypatch.setattr(channels, "YouTubeClient", _youtube_refusing(reason)) + + channels.subscribe(stub_channel, user=user, db=db) + + sub = db.execute( + select(Subscription).where( + Subscription.user_id == user.id, Subscription.channel_id == stub_channel + ) + ).scalar_one() + assert sub is not None + + +@pytest.mark.parametrize("reason", ["quotaExceeded", "<none>", "<unparseable>"]) +def test_any_other_refusal_is_answered_with_a_422(db, make_user, monkeypatch, stub_channel, reason): + user = make_user() + monkeypatch.setattr(channels, "YouTubeClient", _youtube_refusing(reason)) + + with pytest.raises(HTTPException) as caught: + channels.subscribe(stub_channel, user=user, db=db) + + assert caught.value.status_code == 422 diff --git a/backend/tests/test_download_failure_catalog.py b/backend/tests/test_download_failure_catalog.py index af661721..ae7341ab 100644 --- a/backend/tests/test_download_failure_catalog.py +++ b/backend/tests/test_download_failure_catalog.py @@ -125,6 +125,25 @@ def test_the_download_child_knows_the_cookie_went_with_it(db, monkeypatch, tmp_p assert (job.error_code, job.error_detail) == ("login_required", "facebook.cookie_rejected") +def test_a_failure_the_database_would_not_record_is_not_claimed(db, monkeypatch, tmp_path): + """The job is still `running`: the runner reports this with the write's error, and the worker + fails the job. A `download.job.failed` here as well would be a second line, and a false one.""" + u = _user(db, "fb-dbdown@example.com") + a, j = _asset_and_job(db, u, sig="dbdown", asset_status="downloading", job_status="running") + _fail_the_child(monkeypatch, tmp_path, cookie=False) + said = [] + monkeypatch.setattr(pipeline, "_log_download_failed", lambda job_id, *rest: said.append(job_id)) + + def db_down(*a, **k): + raise ConnectionError("the database went away") + + monkeypatch.setattr(pipeline.service, "finalize_if_running", db_down) + + with pytest.raises(ConnectionError): + pipeline._download(j.id, a.id, "url", _REEL, {}, u.id) + assert said == [] + + def test_a_job_meeting_a_failed_shared_asset_gets_the_same_explanation(db): # Before the catalog this path wrote the text and NO code: "Download failed" for the second # job, "Facebook sign-in required" for the first. diff --git a/backend/tests/test_failure_lines.py b/backend/tests/test_failure_lines.py new file mode 100644 index 00000000..80b1f6b4 --- /dev/null +++ b/backend/tests/test_failure_lines.py @@ -0,0 +1,622 @@ +"""E22.5 review round 1: a failure is reported once, with its code, and a repeating one is not a +flood. + +Each case here is a place where the first sweep got the line wrong in one of two directions: a +failure that left no line at all (a download the watchdog killed), or one that left too many (the +same edit failure twice, a warning per segment request, per settings read). +""" + +import json +import logging +import re +import shutil +import subprocess +from pathlib import Path +from types import SimpleNamespace + +import pytest +import yt_dlp + +from app import logs, sysconfig, worker +from app.downloads import pipeline +from app.downloads.stated import StatedFailure +from app.models import DownloadJob, MediaAsset +from app.plex import stream as plex_stream + + +class _Sink(logging.Handler): + 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 events(self, code: str) -> list[dict]: + return [o for o in self.objects() if o.get("event") == code] + + +@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) + + +class _NoDb: + """A session that finds nothing and commits nothing — these cases are about the line.""" + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def get(self, *a, **k): + return None + + def commit(self): + pass + + +@pytest.fixture +def finalized(monkeypatch): + """Whether `finalize_if_running` fires: True unless a case says a route got there first.""" + state = {"fires": True} + monkeypatch.setattr(worker, "SessionLocal", _NoDb) + monkeypatch.setattr(pipeline, "SessionLocal", _NoDb) + fire = lambda db, job_id, **fields: state["fires"] # noqa: E731 + monkeypatch.setattr(worker.service, "finalize_if_running", fire) + return state + + +# --- the worker's own failures --------------------------------------------------------------- +@pytest.mark.parametrize("cause", ["stalled", "timeout"]) +def test_a_download_the_watchdog_kills_leaves_a_coded_line(sink, finalized, cause): + """The child is killed, so it never reports; before this the worker did not either, and a + stalled download failed with no line anywhere.""" + worker._fail_running(42, error="stopped", error_code="network", cause=cause) + + (line,) = sink.events("download.job.failed") + assert line["level"] == "WARNING" + assert line["attrs"] == {"job_id": 42, "error_code": "network", "cause": cause} + + +def test_a_job_a_route_already_stopped_is_not_reported_as_failed(sink, finalized): + finalized["fires"] = False + worker._fail_running(42, error="stopped", error_code="network", cause="stalled") + + assert sink.events("download.job.failed") == [] + + +def test_a_caller_with_its_own_line_is_not_reported_twice(sink, finalized): + worker._fail_running(42, error="Worker error", error_code=None) + + assert sink.events("download.job.failed") == [] + + +def test_a_child_that_died_is_reported_with_its_exit_code(sink, finalized): + worker._fail_running( + 42, error="exited", error_code="unknown", cause="child_exit", exit_code=137 + ) + + (line,) = sink.events("download.job.failed") + assert line["attrs"]["exit_code"] == 137 + + +@pytest.mark.parametrize( + ("fires", "code"), [(True, "download.job.failed"), (False, "download.worker.error")] +) +def test_a_worker_error_is_one_line_that_says_what_it_did_to_the_job(sink, fires, code): + """A route's cancel that landed first is not a failure — the error is still reported, with + its stack, but not as the job failing.""" + try: + raise KeyError("a worker bug") + except KeyError as exc: + worker._report_worker_error(42, exc, "crash", lambda: fires) + + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert line["event"] == code + assert "KeyError" in line["exc"] + + +def test_a_worker_error_is_reported_even_when_failing_the_job_raises(sink): + def db_down(): + raise ConnectionError("the database went away") + + with pytest.raises(ConnectionError): + worker._report_worker_error(42, KeyError("a worker bug"), "crash", db_down) + + (line,) = sink.events("download.worker.error") + assert line["attrs"]["cause"] == "crash" + + +def test_a_crash_the_database_will_not_record_does_not_end_the_worker_thread(monkeypatch, sink): + """The crash handler writes to the database; if that raises too, the thread must go on to + the next job — a dead thread is a download slot gone until the worker restarts.""" + claims = iter([42, 43]) + seen = [] + + def claim(): + job = next(claims, None) + if job is None: + worker._stop.set() + return job + + def crash(job_id): + seen.append(job_id) + raise RuntimeError("boom") + + def db_down(*a, **k): + raise ConnectionError("the database went away") + + monkeypatch.setattr(worker, "_claim_job", claim) + monkeypatch.setattr(worker, "_process_job", crash) + monkeypatch.setattr(worker, "_fail_running", db_down) + monkeypatch.setattr(worker.settings, "download_poll_seconds", 0) + worker._stop.clear() + try: + worker._worker_loop(0) + finally: + worker._stop.clear() + assert seen == [42, 43] + + +class _StoppedProc: + """A child that is still tearing down when the supervisor polls, after a route paused it.""" + + pid = 4242 + returncode = None + + def wait(self, timeout=None): + import subprocess + + raise subprocess.TimeoutExpired("child", timeout or 0) + + +def test_the_worker_stopping_a_paused_child_is_not_a_second_abort_line(monkeypatch, sink): + """The child logs `download.job.aborted` when it notices the pause itself; the worker's line + is its own fact — it had to stop the child — so one pause is never two aborts.""" + monkeypatch.setattr(worker, "_spawn_download_child", lambda job_id: _StoppedProc()) + monkeypatch.setattr(worker, "_job_liveness", lambda job_id: ("paused", 1.0)) + monkeypatch.setattr(worker, "_stop_and_free", lambda *a: None) + + worker._run_supervised(42, 7) + + assert sink.events("download.job.aborted") == [] + assert len(sink.events("download.child.stopped")) == 1 + + +# --- an edit failure, once --------------------------------------------------------------------- +def test_an_edit_failure_is_one_line_with_its_code_and_our_own_stack(sink, finalized): + try: + raise TypeError("a spec shape nobody expected") + except TypeError as exc: + pipeline._fail_edit(9, 3, str(exc), exc) + + (line,) = sink.events("edit.job.failed") + assert line["attrs"] == {"job_id": 9, "asset_id": 3, "error_type": "TypeError"} + assert "TypeError" in line["exc"] + assert len([o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")]) == 1 + + +def test_an_edit_that_ffmpeg_refused_names_no_file_and_carries_no_stack(sink, finalized): + """ffmpeg's stderr tail names its input, whose path is the channel and the title. The message + is scrubbed; the stack is left off, because the message is the whole story.""" + msg = "ffmpeg failed (1): /downloads/Some_Channel/Season_2024/A_Private_Title_a3.mp4: Invalid data" + pipeline._fail_edit(9, 3, msg, StatedFailure(msg)) + + (line,) = sink.events("edit.job.failed") + assert "A_Private_Title" not in json.dumps(line) + assert "exc" not in line + + +def test_an_edit_the_database_would_not_fail_is_not_reported_as_failed(sink, monkeypatch): + """The job is still `running`: the runner reports this failure with the write's, and the + worker fails the job (`child_exit`). A line here as well would be a second, and a false one.""" + + class _Down: + def __enter__(self): + raise ConnectionError("the database went away") + + def __exit__(self, *exc): + return False + + monkeypatch.setattr(pipeline, "SessionLocal", _Down) + with pytest.raises(ConnectionError): + pipeline._fail_edit(9, 3, "boom", KeyError("x")) + + assert sink.events("edit.job.failed") == [] + + +class _EditDb(_NoDb): + """An edit job whose source is ready, for `_process_edit` to get as far as its encode.""" + + def get(self, model, _id): + if model is DownloadJob: + return SimpleNamespace(source_asset_id=7, edit_spec={}, user_id=1) + if model is MediaAsset: + return SimpleNamespace( + status="ready", rel_path="src.mp4", width=640, height=360, duration_s=10 + ) + return None + + +def test_an_edit_that_crashes_is_said_once(sink, finalized, monkeypatch, tmp_path): + """The line `_process_edit`'s handler used to log before `_fail_edit` logged it again.""" + (tmp_path / "src.mp4").write_bytes(b"x") + monkeypatch.setattr(pipeline, "SessionLocal", _EditDb) + monkeypatch.setattr(pipeline.settings, "download_root", str(tmp_path)) + monkeypatch.setattr(pipeline, "_edit_staging_dir", lambda asset_id: tmp_path / "staging") + + def odd_spec(*a, **k): + raise TypeError("a spec shape nobody expected") + + monkeypatch.setattr(pipeline, "_set_job", odd_spec) + + pipeline._process_edit(9, 3) + + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert line["event"] == "edit.job.failed" + assert "TypeError" in line["exc"] + + +def test_an_edit_whose_source_is_gone_is_found_by_the_same_code(sink, finalized): + pipeline._fail_edit(9, 3, "The source file is missing.") + + (line,) = sink.events("edit.job.failed") + assert line["attrs"] == {"job_id": 9, "asset_id": 3} + + +# --- a download failure, scrubbed --------------------------------------------------------------- +def test_a_failed_download_line_does_not_put_back_what_the_adapter_took_out(sink): + """yt-dlp logs its error through the adapter (scrubbed) and then raises the same text, which + the pipeline logs again. Unscrubbed, that second line is the URL the first one hid.""" + msg = "ERROR: Unsupported URL: https://example.org/private/path?id=123" + pipeline._log_download_failed(5, msg, "unknown", yt_dlp.utils.DownloadError(msg)) + + (line,) = sink.events("download.job.failed") + assert "private/path" not in json.dumps(line) + assert "example.org/…" in line["msg"] + # Unclassified, but yt-dlp's own error: its stack is the `except`, its foot the raw text. + assert "exc" not in line + + +@pytest.mark.parametrize( + "exc", + [ + RuntimeError("dictionary changed size during iteration"), + RecursionError("maximum recursion depth exceeded"), + NotImplementedError(), + FileNotFoundError(2, "No such file", "/downloads/Some_Channel/Season_2024/A_Private_Title"), + ], + ids=lambda e: type(e).__name__, +) +def test_a_bug_that_python_raises_keeps_its_stack_and_names_no_file(sink, exc): + """Only the failures WE raise with the whole story in the message go without a stack. The + same types are what Python raises for a bug of ours, and then the stack is the only lead.""" + try: + raise exc + except (RuntimeError, OSError) as caught: + pipeline._log_download_failed(5, str(caught), "unknown", caught) + + (line,) = sink.events("download.job.failed") + assert type(exc).__name__ in line["exc"] + assert "A_Private_Title" not in json.dumps(line) + + +def test_a_stack_does_not_carry_the_download_error_it_was_raised_over(sink): + """A database error raised inside `except DownloadError` has yt-dlp's text as its context, + and a plain `exc_info` prints that link unscrubbed.""" + # A variable, as in the pipeline: a frame prints its SOURCE line, and that is code, not data. + text = "ERROR: [youtube] dQw4w9WgXcQ: Sign in to confirm" + try: + try: + raise yt_dlp.utils.DownloadError(text) + except yt_dlp.utils.DownloadError: + raise ConnectionError("server closed the connection unexpectedly") # noqa: B904 + except ConnectionError as exc: + pipeline._log_download_failed(5, str(exc), "unknown", exc) + + (line,) = sink.events("download.job.failed") + assert "During handling of the above exception" in line["exc"] + assert "Sign in to confirm" in line["exc"] + assert "dQw4w9WgXcQ" not in json.dumps(line) + + +def test_an_unclassified_failure_of_our_own_keeps_its_stack(sink): + try: + raise KeyError("requested_formats") + except KeyError as exc: + pipeline._log_download_failed(5, str(exc), "unknown", exc) + + (line,) = sink.events("download.job.failed") + assert "KeyError" in line["exc"] + assert line["attrs"]["error_type"] == "KeyError" + + +def test_the_metadata_backfill_names_the_asset_and_not_the_download(sink, monkeypatch): + from app.downloads import adapters, backfill + + url = "https://www.youtube.com/watch?v=dQw4w9WgXcQ" + + class _Refusing: + def __init__(self, opts): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def extract_info(self, target, download): + raise yt_dlp.utils.DownloadError( + f"ERROR: [youtube] dQw4w9WgXcQ: Video unavailable ({target})" + ) + + monkeypatch.setattr(backfill.yt_dlp, "YoutubeDL", _Refusing) + assert backfill._extract_meta(url, adapters.YouTubeAdapter(), 11) is None + + lines = [o for o in sink.objects() if "meta extract failed" in o["msg"]] + assert lines and all("dQw4w9WgXcQ" not in json.dumps(o) for o in lines) + + +def test_the_metadata_backfill_takes_out_a_generic_name_whatever_it_holds(sink, monkeypatch): + from app.downloads import adapters, backfill + + url = "https://example.org/v/Our%20Trip%3A%20Day%201.mp4" + + class _Refusing: + def __init__(self, opts): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def extract_info(self, target, download): + raise yt_dlp.utils.DownloadError("ERROR: [generic] Our Trip: Day 1: Unable to download") + + monkeypatch.setattr(backfill.yt_dlp, "YoutubeDL", _Refusing) + assert backfill._extract_meta(url, adapters.SourceAdapter(), 11) is None + + lines = [o for o in sink.objects() if "meta extract failed" in o["msg"]] + assert lines and all("Day 1" not in json.dumps(o) for o in lines) + + +# --- a repeating failure, once ------------------------------------------------------------------ +def test_a_stale_setting_is_reported_once_not_on_every_read(sink, monkeypatch): + spec = next(s for s in sysconfig.SPECS if s.type == "int") + monkeypatch.setattr(sysconfig, "_raw_override", lambda db, key: "not-a-number") + monkeypatch.setattr(sysconfig, "_coerce_warned", set()) + + for _ in range(3): + sysconfig.get(None, spec.key) + + assert len(sink.events("sysconfig.override_uncoercible")) == 1 + + +class _RefusingDir: + """A session directory on a disk that has gone away: every probe raises.""" + + def __truediv__(self, name): + return SimpleNamespace(exists=self._refuse) + + @staticmethod + def _refuse(): + raise PermissionError("the disk went read-only") + + +def test_a_refusing_session_directory_is_reported_once_per_session(sink): + """Every segment request probes, and hls.js retries each 404 — a line per probe is a flood.""" + session = plex_stream.HlsSession("k", Path("."), None, 0.0, ()) + session.dir = _RefusingDir() + + for seq in (3, 4, 5): + assert not plex_stream.artifact_may_arrive(session, plex_stream.segment_name(seq, None)) + + (line,) = sink.events("plex.stream.segment_probe_failed") + assert line["attrs"]["reason"] == "PermissionError" + + +def test_a_retried_attempt_names_the_host_and_not_the_video(sink, monkeypatch, tmp_path): + """The first attempt's DownloadError is logged when the fallback set takes over — one line + before the adapter's scrubbed copy of the same text would have hidden it.""" + url = "https://www.youtube.com/watch?v=dQw4w9WgXcQ" + attempts = iter( + [yt_dlp.utils.DownloadError(f"ERROR: [youtube] dQw4w9WgXcQ: Sign in ({url})"), {"id": "x"}] + ) + + class _YDL: + def __init__(self, opts): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def extract_info(self, target, download): + outcome = next(attempts) + if isinstance(outcome, Exception): + raise outcome + return outcome + + adapter = SimpleNamespace( + client_sets=lambda authed: [["web"], ["tv"]], + resolve_url=lambda target, opts: target, + ydl_opts_extra=lambda clients: {}, + retriable=lambda text: True, + ) + monkeypatch.setattr(pipeline.yt_dlp, "YoutubeDL", _YDL) + monkeypatch.setattr(pipeline, "_touch_job", lambda job_id: None) + monkeypatch.setattr(pipeline, "_set_job", lambda job_id, **fields: None) + + assert pipeline._extract_with_fallback(1, 1, url, {}, tmp_path, adapter) == {"id": "x"} + + (line,) = [o for o in sink.objects() if "retrying with fallback" in o["msg"]] + assert "dQw4w9WgXcQ" not in json.dumps(line) + + +@pytest.mark.skipif(shutil.which("ffmpeg") is None, reason="ffmpeg not available") +def test_a_failed_poster_or_storyboard_names_no_file(sink, tmp_path): + """ffmpeg's CalledProcessError quotes its argv, and the source path in it is built from the + channel and the title.""" + from app.downloads import edit as editmod + + rel = "Some_Channel/Season_2024/Some_Channel_-_20240101_-_A_Private_Title_a3.mp4" + (tmp_path / rel).parent.mkdir(parents=True) + (tmp_path / rel).write_bytes(b"not a video") + asset = SimpleNamespace(id=3, rel_path=rel, duration_s=10.0, storyboard_path=None) + + assert editmod.ensure_poster(asset, str(tmp_path)) is None + assert editmod.ensure_storyboard(asset, str(tmp_path)) is None + + lines = [o["msg"] for o in sink.objects() if "gen skipped" in o["msg"]] + # The whole message: a long tmp root would push a leaked argv's path past any length cut. + assert len(lines) == 2 + assert all( + re.fullmatch(r"\w+ gen skipped for asset 3: CalledProcessError \d+", m) for m in lines + ) + + +@pytest.mark.parametrize( + "err", + [ + subprocess.TimeoutExpired( + ["ffmpeg", "-i", "/downloads/Some_Channel/A_Private_Title.mp4"], 30 + ), + FileNotFoundError(2, "No such file", "/downloads/Some_Channel/A_Private_Title.jpg"), + subprocess.CalledProcessError(1, ["ffmpeg", "-i", "/downloads/Some_Channel/x.mp4"]), + ], + ids=lambda e: type(e).__name__, +) +def test_an_image_step_failure_is_its_kind_and_nothing_it_quotes(err): + from app.downloads import edit as editmod + + code = getattr(err, "returncode", None) + assert editmod._step_failure(err) == " ".join( + [type(err).__name__, *([str(code)] if code is not None else [])] + ) + + +def test_a_thumbnail_that_cannot_be_copied_names_no_file(sink, monkeypatch, tmp_path): + from app.downloads import edit as editmod + + src = tmp_path / "thumb.jpg" + src.write_bytes(b"\xff\xd8\xff rest") + + def refuse(a, b): + raise PermissionError( + 13, "Permission denied", "/downloads/Some_Channel/A_Private_Title.jpg" + ) + + monkeypatch.setattr(editmod.shutil, "copyfile", refuse) + assert editmod.thumbnail_to_jpg(src, tmp_path / "out.jpg") is None + + (line,) = [o for o in sink.objects() if "thumbnail copy failed" in o["msg"]] + assert "Some_Channel" not in json.dumps(line) + + +# --- the child's last stop ------------------------------------------------------------------------ +def test_a_failure_the_child_cannot_record_is_one_scrubbed_line_and_a_non_zero_exit( + sink, monkeypatch +): + """The pipeline's failure write was refused. Python's own hook would print the chain raw — + and its context is the download's failure, the URL in it. The worker fails the job on the + exit code (`child_exit`), so this line does not claim the job failed.""" + from app.downloads import runner + + url = "https://example.org/v/Our%20Trip%3A%20Day%201.mp4" + text = f"ERROR: [generic] Our Trip: Day 1: Unable to download webpage ({url})" + + def download(*a): + try: + raise yt_dlp.utils.DownloadError(text) + except yt_dlp.utils.DownloadError: + raise ConnectionError("the database went away") # noqa: B904 + + monkeypatch.setattr(pipeline, "_download", download) + with pytest.raises(SystemExit) as exited: + runner._run(5, 7, "download", "url", url, {}, 1) + + assert exited.value.code == 1 + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert line["event"] == "download.child.failed" + assert "Unable to download webpage" in line["exc"] + # "Day 1" too: the fallback pattern alone stops at the first `: ` and leaves it. + assert "Trip" not in json.dumps(line) and "Day 1" not in json.dumps(line) + + +def test_a_crash_the_database_will_not_record_carries_its_stack_once(monkeypatch, sink): + claims = iter([42]) + + def claim(): + job = next(claims, None) + if job is None: + worker._stop.set() + return job + + def crash(job_id): + raise RuntimeError("the one crash") + + def db_down(*a, **k): + raise ConnectionError("the database went away") + + monkeypatch.setattr(worker, "_claim_job", claim) + monkeypatch.setattr(worker, "_process_job", crash) + monkeypatch.setattr(worker, "_fail_running", db_down) + monkeypatch.setattr(worker.settings, "download_poll_seconds", 0) + worker._stop.clear() + try: + worker._worker_loop(0) + finally: + worker._stop.clear() + + stacks = [o["exc"] for o in sink.objects() if "exc" in o] + assert sum("the one crash" in s for s in stacks) == 1 + (write,) = sink.events("download.worker.fail_write_failed") + assert "the database went away" in write["exc"] + + +def test_a_watchdog_error_on_a_job_it_failed_is_that_jobs_failure_line( + sink, finalized, monkeypatch +): + """Through the real `_fail_after_kill` → `_fail_running`: the verdict it returns picks the + event, so a lost `return` would log every such failure as a mere worker error.""" + + class _Alive: + pid = 4242 + returncode = None + + def wait(self, timeout=None): + raise subprocess.TimeoutExpired("child", timeout or 0) + + def broken(job_id): + raise KeyError("a watchdog bug") + + monkeypatch.setattr(worker, "_spawn_download_child", lambda job_id: _Alive()) + monkeypatch.setattr(worker, "_job_liveness", broken) + monkeypatch.setattr(worker, "_stop_and_free", lambda *a: None) + + worker._run_supervised(42, 7) + + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert (line["event"], line["attrs"]["cause"]) == ("download.job.failed", "supervisor_error") + assert "a watchdog bug" in line["exc"] diff --git a/backend/tests/test_log_pii.py b/backend/tests/test_log_pii.py new file mode 100644 index 00000000..92a52d73 --- /dev/null +++ b/backend/tests/test_log_pii.py @@ -0,0 +1,407 @@ +"""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" + + +@pytest.fixture +def consented(): + """The request scope of a user who turned Teljes (TRACE) on for themselves.""" + scope = logs._RequestScope() + scope.user_id, scope.level = 7, logs.TRACE + token = logs._scope.set(scope) + try: + yield + finally: + logs._scope.reset(token) + + +def test_the_body_is_kept_for_the_one_user_who_consented_to_it(sink, consented): + _upstream_failure("GET", "search", _youtube_403(TERM)) + + # The diagnostic is not lost, it is gated — on the consent the privacy policy describes. + (trace,) = sink.at("TRACE") + assert TERM in trace["attrs"]["body"] + + +def test_a_process_running_at_trace_is_not_anyones_consent(sink): + """`sink` runs the whole tree at TRACE — what an admin setting `log_level` to TRACE does. That + buys more detail, not every user's search terms quoted back (`logs._traced`).""" + _upstream_failure("GET", "search", _youtube_403(TERM)) + + assert sink.at("TRACE") == [] + assert TERM not in json.dumps(sink.objects()) + + +def test_a_scope_with_no_elevation_is_not_consent(): + scope = logs._RequestScope() + scope.user_id = 7 + token = logs._scope.set(scope) + try: + assert not logs.consented_trace() + finally: + logs._scope.reset(token) + assert not logs.consented_trace() # a scheduler thread: no request at all + + +def test_a_refused_token_refresh_names_the_oauth_reason_and_not_its_prose(sink, monkeypatch): + """The token endpoint's error is `{"error": "<code>", "error_description": <prose>}` — not the + Data API's shape. The refresh goes through the same door, so it gets the same treatment.""" + from types import SimpleNamespace + + from app.youtube import client as yt + + resp = httpx.Response( + 400, + json={"error": "invalid_grant", "error_description": "Token has been expired or revoked."}, + request=httpx.Request("POST", "https://oauth2.googleapis.com/token"), + ) + client = yt.YouTubeClient.__new__(yt.YouTubeClient) # no HTTP client: `_send` is the stub + client.db = None + client.user = SimpleNamespace( + token=SimpleNamespace(access_token=None, expiry=None, refresh_token_enc=b"x") + ) + monkeypatch.setattr(yt, "decrypt_optional", lambda value: None) + monkeypatch.setattr(yt, "decrypt", lambda value: "a-refresh-token") + monkeypatch.setattr(yt.sysconfig, "get_str", lambda db, key: "") + monkeypatch.setattr(client, "_send", lambda *a, **k: resp) + + with pytest.raises(YouTubeError) as caught: + client._access_token() + err = caught.value + + (line,) = sink.at("WARNING") + assert line["attrs"]["reason"] == "invalid_grant" + assert err.reason == "invalid_grant" + assert "revoked" not in str(err) and "revoked" not in json.dumps(line) + + +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", + # A download's path is built from its channel and its title (`storage.rel_path`), so it + # names what someone downloaded exactly as the URL does. Log the asset id. + "rel", + "rel_path", + "title", + } +) +_BANNED_ATTRS = frozenset( + {"text", "content", "email", "url", "query", "rel_path", "title", "display_name"} +) +_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}" + ) + + +_AT_LEAST_DEBUG = {"DEBUG", "INFO", "WARNING", "WARN", "ERROR", "CRITICAL", "FATAL"} + + +def _may_run_at_trace(call: ast.Call) -> bool: + """A `log.log(level, …)` whose level is not provably DEBUG or above: `logs.TRACE`, a bare + `TRACE`, a literal 5 — or a variable, which could be any of them.""" + if call.func.attr != "log" or not call.args: + return False + level = call.args[0] + if isinstance(level, ast.Attribute | ast.Name): + return (level.attr if isinstance(level, ast.Attribute) else level.id) not in _AT_LEAST_DEBUG + if isinstance(level, ast.Constant) and isinstance(level.value, int): + return level.value < logging.DEBUG + return True + + +def _is_consent_check(test: ast.expr) -> bool: + """Exactly `…consented_trace()`: not `not …`, not `x or …` — each of those runs the body when + there is no consent.""" + return ( + isinstance(test, ast.Call) + and isinstance(test.func, ast.Attribute | ast.Name) + and (test.func.attr if isinstance(test.func, ast.Attribute) else test.func.id) + == "consented_trace" + ) + + +def _guarded_by_consent(node: ast.AST, parents: dict[ast.AST, ast.AST]) -> bool: + """The node runs only inside the BODY of an `if <consented_trace()>:` — not its `else`.""" + while node in parents: + parent = parents[node] + if isinstance(parent, ast.If) and _is_consent_check(parent.test) and node in parent.body: + return True + node = parent + return False + + +def _parents(tree: ast.AST) -> dict[ast.AST, ast.AST]: + return {child: node for node in ast.walk(tree) for child in ast.iter_child_nodes(node)} + + +_GATE_SHAPES = { + "the body of the check": ("if logs.consented_trace():\n log.log(logs.TRACE, 'x')", True), + "its else": ( + "if logs.consented_trace():\n pass\nelse:\n log.log(logs.TRACE, 'x')", + False, + ), + "a negated check": ("if not logs.consented_trace():\n log.log(logs.TRACE, 'x')", False), + "an or": ("if debug or logs.consented_trace():\n log.log(logs.TRACE, 'x')", False), + "a nested block in the body": ( + "if logs.consented_trace():\n for t in ts:\n log.log(logs.TRACE, 'x')", + True, + ), +} + + +@pytest.mark.parametrize("shape", list(_GATE_SHAPES)) +def test_the_consent_gate_is_the_body_of_the_check_and_nothing_else(shape): + src, gated = _GATE_SHAPES[shape] + tree = ast.parse(src) + (call,) = [n for n in ast.walk(tree) if isinstance(n, ast.Call) and _is_log_call(n)] + assert _guarded_by_consent(call, _parents(tree)) is gated + + +@pytest.mark.parametrize( + ("level", "trace"), + [ + ("logs.TRACE", True), + ("TRACE", True), + ("5", True), + ("level", True), + ("levels[scope]", True), + ("logging.DEBUG", False), + ("logging.WARNING", False), + ("20", False), + ], +) +def test_a_level_that_may_be_trace_is_treated_as_trace(level, trace): + (call,) = [n for n in ast.walk(ast.parse(f"log.log({level}, 'x')")) if isinstance(n, ast.Call)] + assert _may_run_at_trace(call) is trace + + +def test_every_escaped_trace_line_is_gated_on_the_users_own_consent(): + """`log-pii-ok` on a TRACE line means "this is what the user's Teljes consent is for". The TRACE + level alone does not hold that promise: an admin can run the whole process at TRACE, and a + scheduler thread has no user at all. So the line must sit under `logs.consented_trace()`.""" + 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() + tree = ast.parse(src) + parents = _parents(tree) + for node in ast.walk(tree): + if not _is_log_call(node) or not _offending(node): + continue + span = " ".join(lines[max(0, node.lineno - 2) : (node.end_lineno or node.lineno)]) + if ( + _may_run_at_trace(node) + and _ESCAPE in span + and not _guarded_by_consent(node, parents) + ): + offenders.append(f"{path.relative_to(root)}:{node.lineno}") + assert offenders == [], ( + f"a TRACE line with user content is not under consented_trace(): {offenders}" + ) + + +def test_a_database_error_does_not_carry_the_values_it_was_given(db): + """DB lane. A failed write's message is logged and stored as the job's error text; with its + bound parameters in it, that is the title or the file path the row was about.""" + from sqlalchemy import exc as sa_exc + from sqlalchemy import text + + # Postgres's own text for this one names no value ("value too long for type character + # varying(3)"), so what is left to leak is SQLAlchemy's `[parameters: …]` suffix. + db.execute(text("CREATE TEMP TABLE pii_probe (x varchar(3))")) + with pytest.raises(sa_exc.DBAPIError) as caught: + db.execute(text("INSERT INTO pii_probe VALUES (:v)"), {"v": "A_Private_Title"}) + db.rollback() + assert "value too long" in str(caught.value) + assert "A_Private_Title" not in str(caught.value) diff --git a/backend/tests/test_logger_names.py b/backend/tests/test_logger_names.py new file mode 100644 index 00000000..033e2c1d --- /dev/null +++ b/backend/tests/test_logger_names.py @@ -0,0 +1,121 @@ +"""E22.5 S2 — every module's logger is named after the module. + +The names used to be literals, and 25 of them covered 34 modules: `plex/client.py`, `plex/stream.py`, +`plex/subtitles.py`, `plex/sync.py` and two route modules all called themselves `siftlode.plex`, and +`downloads/pipeline.py` called itself `siftlode.worker`. A level pinned per logger could not separate +them, and neither can E22.6's console filter — the `logger` field is in every stored row precisely so +it can be filtered on. + +So the name is derived, not written: `logs.get_logger(__name__)`. These cases pin the derivation and +the rule, because the rule is only worth having if a hand-rolled name fails the gate. +""" + +import ast +import logging +import pathlib +import sys +import types + +import pytest + +from app import logs + +APP = pathlib.Path(logs.__file__).resolve().parent +_ESCAPE = "logger-name-ok" + + +@pytest.mark.parametrize( + ("module", "expected"), + [ + ("app.plex.sync", "siftlode.plex.sync"), + ("app.plex.stream", "siftlode.plex.stream"), + ("app.routes.channels", "siftlode.routes.channels"), + ("app.worker", "siftlode.worker"), + # A script that is not a module of ours (pytest itself, here): it lands on the root of our + # tree rather than inventing `siftlode.__main__`, which nothing would think to filter on. + ("__main__", "siftlode"), + ], +) +def test_the_name_follows_the_module(module, expected): + assert logs.get_logger(module).name == expected + + +@pytest.mark.parametrize( + ("spec_name", "expected"), + [ + # How the worker and the download child actually run: `python -m app.worker`, and the + # worker's own `[sys.executable, "-m", "app.downloads.runner", ...]`. `__name__` is + # `__main__` in both, and taken at its word both processes logged as the bare root. + ("app.worker", "siftlode.worker"), + ("app.downloads.runner", "siftlode.downloads.runner"), + ], +) +def test_a_module_run_with_dash_m_keeps_its_own_name(monkeypatch, spec_name, expected): + main = types.ModuleType("__main__") + main.__spec__ = types.SimpleNamespace(name=spec_name) + monkeypatch.setitem(sys.modules, "__main__", main) + + assert logs.get_logger("__main__").name == expected + + +def test_a_plain_script_has_no_spec_and_stays_the_root(monkeypatch): + main = types.ModuleType("__main__") + main.__spec__ = None + monkeypatch.setitem(sys.modules, "__main__", main) + + assert logs.get_logger("__main__").name == "siftlode" + + +def test_every_derived_logger_stays_under_the_one_tree(): + """`configure_logging` hangs the level and the handler off the root, and the tests attach their + sink to `siftlode` — a name outside that tree would be invisible to both.""" + for module in ("app.main", "app.plex.sync", "app.routes.plex.people", "app"): + assert logs.get_logger(module).name.startswith("siftlode") + + +def test_the_module_logger_is_reachable_by_its_derived_name(): + """Not a new logger object per call: the stdlib registry is keyed by name, and an operator + pinning `siftlode.plex.sync` has to reach the same instance the module logs through.""" + from app.plex import sync + + assert sync.log is logging.getLogger("siftlode.plex.sync") + + +def test_no_module_hand_rolls_a_logger_name(): + offenders = [] + for path in sorted(APP.rglob("*.py")): + src = path.read_text(encoding="utf-8") + lines = src.splitlines() + for node in ast.walk(ast.parse(src)): + if not isinstance(node, ast.Call): + continue + func = node.func + called = ( + func.attr + if isinstance(func, ast.Attribute) + else func.id + if isinstance(func, ast.Name) + else "" + ) + if called == "get_logger": + # The derivation itself is only as good as its argument: a literal here does not + # name a module, it collapses to the root and pools modules together again. + arg = node.args[0] if len(node.args) == 1 else None + if isinstance(arg, ast.Name) and arg.id == "__name__" and not node.keywords: + continue + elif called == "getLogger": + # A no-argument `logging.getLogger()` is the ROOT logger — level plumbing, not a + # module's own logger, and nothing to name. A `name=` keyword is still a name. + if not node.args and not node.keywords: + continue + else: + continue + start = max(0, node.lineno - 2) # the call's lines, plus the one above it + span = " ".join(lines[start : (node.end_lineno or node.lineno)]) + if _ESCAPE in span: + continue + offenders.append(f"{path.relative_to(APP)}:{node.lineno}") + assert offenders == [], ( + "a module names its own logger; use `logs.get_logger(__name__)`, or say why the name is " + f"not the module's with `# {_ESCAPE}: <why>` — {offenders}" + ) diff --git a/backend/tests/test_logs.py b/backend/tests/test_logs.py index ae8b883e..556db984 100644 --- a/backend/tests/test_logs.py +++ b/backend/tests/test_logs.py @@ -318,3 +318,68 @@ def test_a_failing_request_is_logged_by_status_and_an_unhandled_error_is_logged_ assert payload["level"] == "ERROR" assert payload["event"] == "http.request" assert "RuntimeError" in payload["exc"] + + +# --- a stack whose messages are data (`logs.scrubbed_stack`) ----------------------------------- +def _upper(exc: BaseException) -> str: + return str(exc).upper() + + +def _raised(make): + try: + make() + except Exception as exc: # noqa: BLE001 — whatever the case raised is the case + return exc + raise AssertionError("the case did not raise") + + +def test_a_raise_from_is_printed_as_its_direct_cause(): + def make(): + try: + raise KeyError("inner") + except KeyError as inner: + raise ValueError("outer") from inner + + stack = logs.scrubbed_stack(_raised(make), _upper)["scrubbed_stack"] + assert "The above exception was the direct cause" in stack + assert "During handling" not in stack + assert "'INNER'" in stack and "OUTER" in stack + + +def test_a_raise_from_none_hides_the_link_its_author_hid(): + def make(): + try: + raise KeyError("hidden") + except KeyError: + raise ValueError("shown") from None + + stack = logs.scrubbed_stack(_raised(make), _upper)["scrubbed_stack"] + assert "HIDDEN" not in stack and "SHOWN" in stack + + +def test_a_chain_that_loops_back_ends(): + a, b = ValueError("a"), ValueError("b") + a.__context__, b.__context__ = b, a + assert "A" in logs.scrubbed_stack(a, _upper)["scrubbed_stack"] + + +def test_a_message_that_cannot_be_rendered_does_not_fail_the_report(): + def refuse(exc): + raise RuntimeError("no") + + assert ( + logs.scrubbed_stack(ValueError("x"), refuse)["scrubbed_stack"] + == "ValueError: <unprintable>" + ) + + +def test_the_text_format_carries_the_scrubbed_stack_too(): + title = "a private title" # a variable: a frame prints its source line, which is code + exc = ValueError(title) + record = logging.LogRecord("siftlode.x", logging.WARNING, __file__, 1, "failed", None, None) + for key, value in logs.scrubbed_stack(exc, lambda e: "…").items(): + setattr(record, key, value) + + line = logs.TextFormatter().format(record) + assert "ValueError: …" in line and "private" not in line + assert "scrubbed_stack" not in line # the stack, not an attribute diff --git a/backend/tests/test_logsink.py b/backend/tests/test_logsink.py index 1e166d5c..7b9eb7cf 100644 --- a/backend/tests/test_logsink.py +++ b/backend/tests/test_logsink.py @@ -90,6 +90,40 @@ def test_a_flood_of_one_message_is_stored_up_to_the_limit_and_then_summarised(st assert notice.attrs["template"] == "RSS poll skipped for channel %s: HTTP 404" +def test_a_pass_through_template_groups_by_its_text_not_by_the_bare_placeholder(stored): + """`"%s"` is how the yt-dlp adapter hands over yt-dlp's own line, and as a key it says nothing: + every distinct warning would share one bucket and the thirty-first — whatever it said — would be + dropped as a "repeat" of the first. The text groups instead, numbers folded, so a retry storm is + still one repeat and the warning that explains the failure still gets through.""" + sink, log, rows = stored + limit = logsink.REPEATS_PER_MINUTE + for i in range(limit + 10): + log.warning("%s", f"[download] Got error: timed out. Retrying fragment {i} (1/10)...") + log.warning("%s", "[youtube] …: Requested format is not available") + stored_rows = rows() + assert len(stored_rows) == limit + 1 + assert stored_rows[-1].msg == "[youtube] …: Requested format is not available" + sink._repeats.started -= logsink.REPEAT_WINDOW_SECONDS + notice = rows()[-1] + assert notice.attrs["suppressed"] == 10 + assert notice.attrs["template"].startswith( + "[download] Got error: timed out. Retrying fragment #" + ) + + +def test_a_process_that_ends_inside_the_minute_still_says_what_it_dropped(stored): + """Every download child lives well under the limiter's minute. Its last batch closes the window + early, or the repeats it dropped would go unreported.""" + sink, log, rows = stored + for i in range(logsink.REPEATS_PER_MINUTE + 3): + log.warning("RSS poll skipped for channel %s: HTTP 404", f"UC{i}") + rows() + sink.write_pending(final=True) + notice = rows()[-1] + assert notice.event == "log.repeats_suppressed" + assert notice.attrs["suppressed"] == 3 + + def test_request_lines_are_never_treated_as_a_flood(stored): _sink, log, rows = stored for _ in range(logsink.REPEATS_PER_MINUTE + 5): @@ -225,7 +259,9 @@ def test_the_writer_drains_what_was_queued_when_it_is_stopped(db): log.addHandler(sink) try: for i in range(logsink.BATCH_MAX + 5): - log.warning(f"line {i}") # distinct templates: no flood limiter involved + # noqa G004: the f-string is the POINT — a distinct rendered message per line is + # what keeps the flood limiter (which groups by template) out of this case. + log.warning(f"line {i}") # noqa: G004 finally: log.removeHandler(sink) sink._stopping.set() @@ -235,6 +271,23 @@ def test_the_writer_drains_what_was_queued_when_it_is_stopped(db): ) +def test_a_stopped_writer_says_what_it_dropped_before_it_goes(db): + """The download child's exit is `stop()` → `_run`'s drain: the notice for the repeats it + dropped is written there, or a child that lived under a minute never reports them.""" + sink = logsink.LogSink(engine) + log = logging.getLogger("siftlode.sinktest.dropped") + log.addHandler(sink) + try: + for i in range(logsink.REPEATS_PER_MINUTE + 4): + log.warning("RSS poll skipped for channel %s: HTTP 404", f"UC{i}") + finally: + log.removeHandler(sink) + sink._stopping.set() + sink._run() + last = db.execute(select(LogEvent).order_by(LogEvent.id.desc()).limit(1)).scalar_one() + assert (last.event, last.attrs["suppressed"]) == ("log.repeats_suppressed", 4) + + def test_the_running_sink_keeps_the_base_level_for_everyone_the_elevation_is_not_for( db, monkeypatch ): diff --git a/backend/tests/test_swallowed_exceptions.py b/backend/tests/test_swallowed_exceptions.py new file mode 100644 index 00000000..5e1343b7 --- /dev/null +++ b/backend/tests/test_swallowed_exceptions.py @@ -0,0 +1,71 @@ +"""E22.5 S3 — every swallowed exception has been ruled on. + +A handler that neither logs nor re-raises is a decision: someone looked at it and decided the +failure is not worth a line. 114 of them were in `app/` at the start of this epic, and almost none +carried that decision anywhere — which means nobody could tell the deliberate ones from the ones +that were never thought about. That is the whole defect: not that they are silent, but that their +silence says nothing. + +So the rule is not "log everything". It is: a silent handler carries `# silent-ok: <why>` on the +`except` line or the line above it. Ruff's S110 and BLE001 sit under this and catch the two narrow +shapes (`except: pass`, blind `except Exception`); this case covers the rest — the handler that +quietly returns a fallback, or `continue`s past one item of a loop. +""" + +import ast +import pathlib + +from app import logs + +APP = pathlib.Path(logs.__file__).resolve().parent +_MARKER = "silent-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 _swallows(handler: ast.ExceptHandler) -> bool: + """Neither reports nor re-raises. A nested `raise` counts: the caller still finds out.""" + for node in ast.walk(handler): + if isinstance(node, ast.Raise) or _is_log_call(node): + return False + return True + + +def test_every_silent_handler_says_why_it_is_silent(): + offenders = [] + for path in sorted(APP.rglob("*.py")): + src = path.read_text(encoding="utf-8") + lines = src.splitlines() + for node in ast.walk(ast.parse(src)): + if not isinstance(node, ast.ExceptHandler) or not _swallows(node): + continue + # The marker may sit in the comment block attached above the `except`, on the + # `except` line itself, or anywhere inside the handler — all three are this handler + # and nothing else, so no justification can excuse a neighbour. + start = node.lineno - 1 + while start > 0 and lines[start - 1].lstrip().startswith("#"): + start -= 1 + end = node.end_lineno or node.lineno + if _MARKER in " ".join(lines[start:end]): + continue + offenders.append(f"{path.relative_to(APP)}:{node.lineno}") + assert offenders == [], ( + f"{len(offenders)} exception handlers neither log nor re-raise and do not say why. Add a " + f"log line with an event code, or `# {_MARKER}: <why the failure is not worth a line>` — " + f"{offenders}" + ) diff --git a/backend/tests/test_worker_supervisor.py b/backend/tests/test_worker_supervisor.py index bc4adb38..53818780 100644 --- a/backend/tests/test_worker_supervisor.py +++ b/backend/tests/test_worker_supervisor.py @@ -87,6 +87,7 @@ def test_no_progress_stall_kills_and_fails_the_job(monkeypatch, rec): fail = next(c for c in rec if c[0] == "fail") assert fail[2]["error_code"] == "network" assert "stalled" in fail[2]["error"].lower() + assert fail[2]["cause"] == "stalled" # the line the killed child never gets to write def test_route_pause_kills_but_keeps_the_route_status(monkeypatch, rec): @@ -120,6 +121,7 @@ def test_wall_clock_cap_kills_even_while_progressing(monkeypatch, rec): worker._run_supervised(1, 99) fail = next(c for c in rec if c[0] == "fail") assert "time limit" in fail[2]["error"].lower() + assert fail[2]["cause"] == "timeout" def test_child_crash_without_finishing_is_failed(monkeypatch, rec): @@ -131,6 +133,8 @@ def test_child_crash_without_finishing_is_failed(monkeypatch, rec): assert "reset_asset" in names fail = next(c for c in rec if c[0] == "fail") assert "unexpectedly" in fail[2]["error"].lower() + # Its line is `_fail_running`'s, so it is logged only if the job really failed here. + assert (fail[2]["cause"], fail[2]["exit_code"]) == ("child_exit", 1) def test_child_nonzero_exit_that_already_set_state_is_left_alone(monkeypatch, rec): @@ -258,7 +262,7 @@ def test_a_crashed_jobs_crash_line_and_cleanup_carry_the_job_id(monkeypatch): monkeypatch.setattr(worker, "_claim_job", claim) monkeypatch.setattr(worker, "_process_job", crash) monkeypatch.setattr( - worker.log, "exception", lambda *a, **k: seen.setdefault("crash", logs._job_id.get()) + worker.log, "error", lambda *a, **k: seen.setdefault("crash", logs._job_id.get()) ) monkeypatch.setattr( worker, "_fail_running", lambda *a, **k: seen.setdefault("cleanup", logs._job_id.get()) diff --git a/backend/tests/test_ytdlp_logging.py b/backend/tests/test_ytdlp_logging.py new file mode 100644 index 00000000..02950256 --- /dev/null +++ b/backend/tests/test_ytdlp_logging.py @@ -0,0 +1,233 @@ +"""E22.5 S4 — yt-dlp explains itself to our log, not to a stdout nobody reads. + +`quiet: True` was doing more than quieting: with no `logger`, yt-dlp's whole account of a download +went to the child process's stdout, so "Requested format is not available", a signature-extraction +failure or a POT refusal reached us only as whatever text happened to end up in the raised +exception. A failed download's real reason was routinely one line the app never kept. + +Measured against yt-dlp 2026.07.04 (the pinned version): with `logger` set, yt-dlp calls `debug` +for its extraction and progress lines and `warning`/`error` for the rest, and neither `quiet` nor +`no_warnings` gates those calls. The cases below pin what we do with them. +""" + +import json +import logging + +import pytest + +from app import logs +from app.downloads import formats + +URL = "https://www.youtube.com/watch?v=dQw4w9WgXcQ&list=PLsomething" + + +class _Sink(logging.Handler): + """The stdout handler's own filter and formatter, so a case sees the bytes a deployment writes.""" + + 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] + + +@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) + + +@pytest.mark.parametrize( + ("method", "level"), + [ + # Several lines per second during a download, and TRACE is the level a user turns on for + # their own session — so the noisy half is exactly the half the consent gates. + ("debug", "TRACE"), + ("info", "DEBUG"), + ("warning", "WARNING"), + # yt-dlp calls `error` from `trouble()` just before it raises, on every failed ATTEMPT — + # the pipeline's fallback client set then often succeeds. The job's verdict is the + # pipeline's `download.job.failed`, not this. + ("error", "WARNING"), + ], +) +def test_each_ytdlp_level_lands_where_it_belongs(sink, method, level): + getattr(formats._YDL_LOG, method)("something happened") + + (line,) = sink.objects() + assert line["level"] == level + assert line["event"] == "download.ytdlp" + assert "something happened" in line["msg"] + + +def test_the_source_url_does_not_travel_with_the_explanation(sink): + formats._YDL_LOG.error(f"ERROR: [youtube] {URL}: Requested format is not available") + + (line,) = sink.objects() + # The host survives — it is what says which extractor is failing. The rest is a row of this + # person's download history, and the job id already names the job on every one of these lines. + assert "www.youtube.com/…" in line["msg"] + assert "dQw4w9WgXcQ" not in json.dumps(line) + assert "list=PLsomething" not in json.dumps(line) + assert "Requested format is not available" in line["msg"] + + +@pytest.mark.parametrize( + ("line", "kept", "gone"), + [ + # The shape nearly every yt-dlp warning and error has: no URL, the id as a prefix. + ( + "ERROR: [youtube] dQw4w9WgXcQ: Video unavailable", + "ERROR: [youtube] …: Video unavailable", + "dQw4w9WgXcQ", + ), + # The generic extractor's "id" is the URL's own basename. + ( + "WARNING: [generic] my-private-holiday-clip: Falling back on generic information", + "WARNING: [generic] …: Falling back on generic information", + "my-private-holiday-clip", + ), + # ...percent-decoded, so it can have spaces: `https://x/My%20Holiday%20in%20Crete.mp4`. + ( + "ERROR: [generic] My Holiday in Crete: Unable to download webpage: HTTP Error 404", + "ERROR: [generic] …: Unable to download webpage: HTTP Error 404", + "Holiday", + ), + ( + "[generic] My Holiday in Crete: Downloading webpage", + "[generic] …: Downloading webpage", + "Holiday", + ), + # A playlist URL is extracted too (`playlist_items: "1"`), and its title is printed. + ( + "[youtube:tab] Playlist Our Wedding Videos: Downloading 1 items of 12", + "[youtube:tab] Playlist …: Downloading 1 items of 12", + "Wedding", + ), + ( + "[download] Finished downloading playlist: Our Wedding Videos", + "[download] Finished downloading playlist: …", + "Wedding", + ), + ( + "[download] Downloading playlist: Our Wedding Videos", + "[download] Downloading playlist: …", + "Wedding", + ), + # An id quoted mid-sentence. + ( + "hu subtitles not available for dQw4w9WgXcQ", + "hu subtitles not available for …", + "dQw4w9WgXcQ", + ), + # `watch?v=…&list=…` under `noplaylist` (`_yes_playlist`), and the multifeed shape. + ( + "[youtube:tab] Downloading just the video dQw4w9WgXcQ because of --no-playlist", + "[youtube:tab] Downloading just the video … because of --no-playlist", + "dQw4w9WgXcQ", + ), + ( + "[youtube] Downloading just video dQw4w9WgXcQ because of --no-playlist", + "[youtube] Downloading just video … because of --no-playlist", + "dQw4w9WgXcQ", + ), + # `Destination` is yt-dlp's word, not an id; the path after it is built from the title. + ( + "[download] Destination: /downloads/Some_Channel/Season_2024/A_Private_Title_a7.mp4", + "[download] Destination: …", + "A_Private_Title", + ), + ], +) +def test_what_names_the_download_comes_out_of_real_ytdlp_shapes(sink, line, kept, gone): + formats._YDL_LOG.warning(line) + + (obj,) = sink.objects() + assert obj["msg"] == kept + assert gone not in json.dumps(obj) + + +@pytest.mark.parametrize( + ("url", "name"), + [ + ("https://example.org/v/Wedding%20%5B2024%5D.mp4", "Wedding [2024]"), + ("https://example.org/v/Our%20Trip%3A%20Day%201.mp4", "Our Trip: Day 1"), + ], +) +def test_the_jobs_own_generic_name_is_taken_out_whatever_it_holds(url, name): + """Brackets and `: ` bound no pattern; the job knows its URL, so the exact name goes.""" + line = f"ERROR: [generic] {name}: Unable to download webpage: HTTP Error 404: Not Found" + + assert formats.generic_id(url) == name + with formats.hiding(url): + assert formats.log_safe(line) == ( + "ERROR: [generic] …: Unable to download webpage: HTTP Error 404: Not Found" + ) + + +def test_the_generic_name_is_yt_dlps_own(): + from yt_dlp.extractor.common import InfoExtractor + + for url in ("https://x.org/a/My%20Holiday.mp4", "https://x.org/a/clip/", "https://x.org/b"): + assert formats.generic_id(url) == InfoExtractor._generic_id(url) + + +def test_a_download_error_is_scrubbed_the_same_way_wherever_it_is_logged(): + """yt-dlp raises the text it has just logged, and the pipeline logs the exception again one + line later (`download.job.failed`). The same scrub, or that line puts the URL back.""" + text = "ERROR: Unsupported URL: https://example.org/private/path?id=123" + + assert formats.log_safe(text) == "ERROR: Unsupported URL: example.org/…" + + +@pytest.mark.parametrize( + "line", + [ + "nsig extraction failed: Some formats may be missing", + "[VideoConvertor] Converting video from webm to mp4; Destination: x", + "[download] 53.2% of ~ 12.00MiB at 1.20MiB/s ETA 00:05", + "[download] 100% of 12.00MiB in 00:00:03 at 3.90MiB/s", + ], +) +def test_a_line_that_names_nothing_keeps_its_words(line): + """The scrub takes out what names a download, and nothing an operator reads the line for.""" + assert formats.log_safe(line) == line + + +def test_a_line_with_no_url_is_left_alone(sink): + formats._YDL_LOG.warning("nsig extraction failed: Some formats may be missing") + + (line,) = sink.objects() + assert "nsig extraction failed: Some formats may be missing" in line["msg"] + + +def test_the_download_options_carry_the_logger(): + opts = formats.build_ydl_opts({}, "%(id)s.%(ext)s", lambda d: None) + + assert opts["logger"] is formats._YDL_LOG + + +def test_a_source_adapter_cannot_silence_it(): + """`extra` is the adapter's own options (YouTube's player-client/POT strategy), merged wholesale. + The logger is set after that merge for the same reason `cookiefile` and the size cap are: an + adapter must not be able to take away the one account of what went wrong that a failed job + leaves behind.""" + opts = formats.build_ydl_opts( + {}, "%(id)s.%(ext)s", lambda d: None, extra={"logger": None, "quiet": False} + ) + + assert opts["logger"] is formats._YDL_LOG diff --git a/frontend/src/lib/releaseNotes.ts b/frontend/src/lib/releaseNotes.ts index ca9331e3..5306cb98 100644 --- a/frontend/src/lib/releaseNotes.ts +++ b/frontend/src/lib/releaseNotes.ts @@ -14,6 +14,21 @@ export interface ReleaseEntry { } export const RELEASE_NOTES: ReleaseEntry[] = [ + { + version: "0.89.0", + date: "2026-09-19", + summary: + "A release for the log rather than for the screen: what the server writes down when something fails is now complete, said once, and free of what you downloaded or searched for.", + fixes: [ + "A download that failed because the server lost its database for a moment no longer shows the video's title and file path inside the database's own error message.", + ], + chores: [ + "No log line carries what a person typed, watched or downloaded: search terms, titles, channel names, file paths, links and video ids are taken out — also from yt-dlp's and ffmpeg's own text, from error stacks, and from database errors. The one exception is Full diagnostics, and only under the user's own consent.", + "Every one of the backend's 114 swallowed exceptions was ruled on: 44 now leave a line with an event code, the other 70 say in the code why they need none — and a test keeps it that way. A failure is logged once, with its stack when it is our own bug, and a stalled or killed download no longer fails without a line.", + "yt-dlp's own explanations (“Requested format is not available”, a sign-in wall) reach the log instead of a stdout nobody read, and a burst of identical lines is summarised instead of flooding the stored log.", + "Three adversarial review rounds: 49 findings raised, 42 survived three independent attempts to refute them, all fixed, and every regression test was proven to fail with its own fix removed.", + ], + }, { version: "0.88.0", date: "2026-09-18", diff --git a/scripts/e2e_seed.py b/scripts/e2e_seed.py index 18a143e7..620aeecc 100644 --- a/scripts/e2e_seed.py +++ b/scripts/e2e_seed.py @@ -166,7 +166,8 @@ def main() -> None: saved = svid.id db.commit() - print( + # noqa T201: this script's stdout IS its interface — the e2e runner parses this JSON. + print( # noqa: T201 json.dumps( { "ok": True,