From 6b0401b922edddeb3457253d4576bcd08aa0b6c5 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Fri, 18 Sep 2026 01:20:42 +0200 Subject: [PATCH] fix(logs): rule on every swallowed exception in the backend MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 114 exception handlers neither logged nor re-raised. The defect was never that they are silent — plenty of them should be — it is that their silence said nothing, so nobody could tell a decision from an oversight. Each one has now been read. 44 got a line; the other 70 carry `# silent-ok: `. What the silent ones had been hiding, in the cases that got a line: - A failed ffprobe sent every HDR file down the 8-bit pipeline, so playback degraded to a software transcode with nothing saying why; a failed audio probe collapsed a multi-audio file to one track and the player showed no language picker; a failed first-PTS probe left subtitles seconds out of sync. - A subtitle sidecar that existed but would not parse made a PARTIAL track read as complete, permanently — the viewer loses every cue past the cached window. - An unreadable crop/trim/cut-list in an edit spec was dropped, so the clip came out uncropped, untrimmed, or shorter than the one the user built. - A dropped `max_height` downloaded at best quality against an explicit cap. - A failed videos.list enrich made every candidate undroppable-from-judgement and therefore dropped: a working search rendered as "no results". - An unusable password hash answered as "wrong password", locking the owner out and telling them they mistyped; a rotated TOKEN_ENCRYPTION_KEY turned every stored token into "not connected". - A stored admin setting that would not coerce fell back to the env default while the settings page went on showing the saved value. - A one-off InnerTube config failure pinned the whole process to the hard-coded fallback key, and searches return nothing when that goes stale. - The HLS sweep reported 0 swept — like a clean run — when it could not list its own root, leaving every crashed session's segments on disk forever. Four of them are counted rather than logged per item (dropped cues, dropped cut list segments, unreclaimed GC files) and reported once per call, because the alternative is one line per cue over a whole subtitle track. ruff gains S110 and BLE001. Every blind `except Exception` that remains carries `# noqa: BLE001 — `, which is the point: catching everything is sometimes right, and always worth a sentence. plex/sync.py's three best-effort backfill catches now keep the traceback — a blind catch over a batch that fetches AND writes could be Plex, the database or our own bug, and `%s` of the exception told them apart badly. main.py's boot-time log-level read likewise. logs.event's `code` is positional-only now: `event("x", code=...)` was a TypeError, and `code` is exactly the word a caller reaches for when the thing that failed has one of its own. tests/test_swallowed_exceptions.py is the wider rule ruff cannot see: a handler that neither logs nor re-raises must say why. Both cases mutation-checked — a marker removed and a log line removed each fail it, naming the handler. --- backend/app/auth.py | 17 ++- backend/app/config.py | 2 + backend/app/discover/pins.py | 2 + backend/app/downloads/edit.py | 59 +++++++++- backend/app/downloads/formats.py | 12 ++- backend/app/downloads/gc.py | 13 ++- backend/app/downloads/links.py | 2 + backend/app/downloads/og.py | 2 + backend/app/downloads/pipeline.py | 41 ++++++- backend/app/downloads/probe.py | 2 + backend/app/downloads/service.py | 2 + backend/app/downloads/storage.py | 24 ++++- backend/app/logs.py | 10 +- backend/app/logsink.py | 12 ++- backend/app/main.py | 8 +- backend/app/plex/client.py | 15 ++- backend/app/plex/detail.py | 2 + backend/app/plex/imgcache.py | 15 ++- backend/app/plex/paths.py | 13 ++- backend/app/plex/stream.py | 86 +++++++++++++-- backend/app/plex/subtitles.py | 119 +++++++++++++++++++-- backend/app/plex/sync.py | 30 ++++-- backend/app/plex/tmdb.py | 18 +++- backend/app/plex/watch_sync.py | 22 +++- backend/app/ratelimit.py | 2 + backend/app/realtime.py | 15 ++- backend/app/routes/auth.py | 7 +- backend/app/routes/channels.py | 33 +++++- backend/app/routes/downloads.py | 2 + backend/app/routes/feed.py | 4 + backend/app/routes/messages.py | 2 + backend/app/routes/plex/detail.py | 69 ++++++++++-- backend/app/routes/search.py | 13 +++ backend/app/security.py | 26 ++++- backend/app/sync/autotag.py | 8 +- backend/app/sync/playlists.py | 32 +++++- backend/app/sync/runner.py | 8 +- backend/app/sync/subscriptions.py | 4 + backend/app/sync/videos.py | 2 + backend/app/sysconfig.py | 10 +- backend/app/worker.py | 17 ++- backend/app/youtube/client.py | 4 +- backend/app/youtube/search_scrape.py | 13 ++- backend/app/youtube/shorts.py | 2 + backend/ruff.toml | 12 ++- backend/tests/conftest.py | 4 +- backend/tests/test_swallowed_exceptions.py | 71 ++++++++++++ 47 files changed, 792 insertions(+), 96 deletions(-) create mode 100644 backend/tests/test_swallowed_exceptions.py diff --git a/backend/app/auth.py b/backend/app/auth.py index ab9bd6ac..b8044a9c 100644 --- a/backend/app/auth.py +++ b/backend/app/auth.py @@ -220,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) @@ -303,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 @@ -374,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/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/edit.py b/backend/app/downloads/edit.py index 161591a9..dfa07932 100644 --- a/backend/app/downloads/edit.py +++ b/backend/app/downloads/edit.py @@ -71,7 +71,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 +86,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 +95,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 +130,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 +328,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 +354,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 +374,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,6 +391,8 @@ 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() @@ -406,6 +437,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) @@ -473,7 +506,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 @@ -527,7 +566,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 @@ -672,6 +717,8 @@ 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 @@ -681,6 +728,8 @@ def _is_jpeg(path: Path) -> bool: 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 diff --git a/backend/app/downloads/formats.py b/backend/app/downloads/formats.py index cc05becf..f9c2202b 100644 --- a/backend/app/downloads/formats.py +++ b/backend/app/downloads/formats.py @@ -20,6 +20,10 @@ spec shape (all keys optional; defaults + browser-playability clamp applied by ` import hashlib import json +from app import logs + +log = logs.get_logger(__name__) + # Fields that affect the produced file — and therefore the cache identity. _SIG_KEYS = ( "mode", @@ -78,7 +82,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]) diff --git a/backend/app/downloads/gc.py b/backend/app/downloads/gc.py index f3a4e6a1..60267f98 100644 --- a/backend/app/downloads/gc.py +++ b/backend/app/downloads/gc.py @@ -97,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 @@ -109,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()), @@ -118,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 c9692a84..e07d4300 100644 --- a/backend/app/downloads/pipeline.py +++ b/backend/app/downloads/pipeline.py @@ -97,6 +97,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 @@ -137,7 +139,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(): @@ -379,8 +388,17 @@ def _extract_with_fallback( 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 @@ -637,7 +655,16 @@ def _download( phase=None, ) db.commit() - log.warning("job %s failed: %s", job_id, msg) + # The traceback only when the classifier could not place it: a recognised yt-dlp + # failure is fully described by its code, and the stack under it is always this same + # `except`. An UNRECOGNISED one leaves nothing else to work from. + log.warning( + "job %s failed: %s", + job_id, + msg, + extra=logs.event("download.job.failed", job_id=job_id, error_code=diagnosis.code), + exc_info=diagnosis.code in (None, "", "unknown"), + ) 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). @@ -757,6 +784,12 @@ def _process_edit(job_id: int, asset_id: int) -> None: _reset_asset_pending(asset_id) log.info("edit job %s aborted (pause/cancel)", job_id) except Exception as exc: # noqa: BLE001 — surface the failure, keep the worker alive + # `_fail_edit` stores `str(exc)` for the user, which is the wrong half for whoever has to + # fix it: an edit reaching here is by definition unclassified, so the stack is all there is. + log.exception( + "the edit job failed", + extra=logs.event("edit.job.failed", job_id=job_id, asset_id=asset_id), + ) _fail_edit(job_id, asset_id, str(exc)[:500]) 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/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/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/logs.py b/backend/app/logs.py index 11fc15b7..121f43a7 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -152,11 +152,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} @@ -314,6 +318,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})" diff --git a/backend/app/logsink.py b/backend/app/logsink.py index edd65157..e74252a5 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -202,6 +202,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 @@ -213,6 +215,8 @@ class LogSink(logging.Handler): ) 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 @@ -224,6 +228,7 @@ class LogSink(logging.Handler): 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,6 +239,7 @@ 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())) @@ -254,9 +260,9 @@ 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 - # 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. + # 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]}", diff --git a/backend/app/main.py b/backend/app/main.py index d0ebc429..5896a885 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -73,10 +73,10 @@ 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}" diff --git a/backend/app/plex/client.py b/backend/app/plex/client.py index 23efb475..8701b6ce 100644 --- a/backend/app/plex/client.py +++ b/backend/app/plex/client.py @@ -105,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 []: @@ -138,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 db518f02..dcf92651 100644 --- a/backend/app/plex/stream.py +++ b/backend/app/plex/stream.py @@ -230,7 +230,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(): @@ -259,7 +267,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 @@ -445,6 +460,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 @@ -471,7 +488,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 [] @@ -580,8 +604,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 @@ -590,10 +620,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) @@ -865,7 +903,20 @@ 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. Per-segment, but the sink groups by message template, so a + # broken session is one grouped line rather than one per segment. + 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 @@ -882,12 +933,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) @@ -920,7 +975,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): @@ -930,7 +994,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 c840e687..cfd04051 100644 --- a/backend/app/plex/subtitles.py +++ b/backend/app/plex/subtitles.py @@ -38,6 +38,7 @@ import subprocess import tempfile import threading import time +import logging from concurrent.futures import ThreadPoolExecutor from pathlib import Path @@ -103,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: @@ -120,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: @@ -130,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) @@ -161,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 @@ -174,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 @@ -205,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) @@ -215,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 @@ -225,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: @@ -234,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 @@ -266,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" @@ -294,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}" @@ -309,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 @@ -651,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 @@ -828,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 5f1c1934..271a2d9f 100644 --- a/backend/app/plex/sync.py +++ b/backend/app/plex/sync.py @@ -100,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 @@ -110,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 @@ -118,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 @@ -133,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 @@ -264,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: @@ -283,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 @@ -323,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) @@ -370,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 ab8b3ccc..f373d072 100644 --- a/backend/app/plex/tmdb.py +++ b/backend/app/plex/tmdb.py @@ -140,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: @@ -497,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 4258c492..47c014d3 100644 --- a/backend/app/plex/watch_sync.py +++ b/backend/app/plex/watch_sync.py @@ -17,6 +17,10 @@ and the incremental pull resolves a genuine divergence to Plex's state (see `_pu running a last-write-wins comparison. """ +# 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 @@ -146,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: @@ -324,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 @@ -564,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: @@ -615,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 c773731c..0f29e086 100644 --- a/backend/app/realtime.py +++ b/backend/app/realtime.py @@ -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 df9f8f30..6d135751 100644 --- a/backend/app/routes/auth.py +++ b/backend/app/routes/auth.py @@ -901,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 diff --git a/backend/app/routes/channels.py b/backend/app/routes/channels.py index bd21b2a9..f97a98eb 100644 --- a/backend/app/routes/channels.py +++ b/backend/app/routes/channels.py @@ -165,7 +165,14 @@ 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: `_upstream_failure` already + # logged the structured `youtube.api.error`, and the message carries method, path, + # status and reason. 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) @@ -189,7 +196,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 [ @@ -297,7 +308,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( @@ -581,7 +598,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/detail.py b/backend/app/routes/plex/detail.py index f2bcfc7e..09386461 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,14 @@ 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 + except Exception: # noqa: BLE001 — playback works without the extras; never 500 here + # Best-effort, but not free: what this 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. + 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), + ) # 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 +425,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/search.py b/backend/app/routes/search.py index cfe540e3..12bf35b9 100644 --- a/backend/app/routes/search.py +++ b/backend/app/routes/search.py @@ -130,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 @@ -159,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 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/sync/autotag.py b/backend/app/sync/autotag.py index cc0f8c78..471bebf7 100644 --- a/backend/app/sync/autotag.py +++ b/backend/app/sync/autotag.py @@ -28,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/playlists.py b/backend/app/sync/playlists.py index 1a4c6ec1..ece2c3f2 100644 --- a/backend/app/sync/playlists.py +++ b/backend/app/sync/playlists.py @@ -57,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() @@ -439,7 +449,13 @@ class _Breaker: return FAILED try: out = op() - except YouTubeError: + except YouTubeError as exc: + # The client logged the call, but not WHICH item it was for — and the caller's failure + # list only ever reaches the user as a count. + log.debug( + "a playlist write to YouTube failed", + extra=logs.event("sync.playlist.item_push_failed", reason=exc.reason), + ) on_fail() self.hit(False) return FAILED @@ -531,7 +547,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: diff --git a/backend/app/sync/runner.py b/backend/app/sync/runner.py index 76498ea0..7220620c 100644 --- a/backend/app/sync/runner.py +++ b/backend/app/sync/runner.py @@ -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 b828ef2f..bf964093 100644 --- a/backend/app/sync/subscriptions.py +++ b/backend/app/sync/subscriptions.py @@ -16,6 +16,8 @@ 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 dee4aac9..007cd38c 100644 --- a/backend/app/sysconfig.py +++ b/backend/app/sysconfig.py @@ -267,7 +267,15 @@ 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. + 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 bc194888..b1ef63ac 100644 --- a/backend/app/worker.py +++ b/backend/app/worker.py @@ -218,8 +218,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: @@ -229,6 +238,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( @@ -305,6 +316,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) diff --git a/backend/app/youtube/client.py b/backend/app/youtube/client.py index 54f1d4f3..04ee7482 100644 --- a/backend/app/youtube/client.py +++ b/backend/app/youtube/client.py @@ -39,7 +39,9 @@ def _error_reason(resp: httpx.Response) -> str: try: errors = resp.json().get("error", {}).get("errors") or [] reasons = ",".join(e.get("reason", "") for e in errors if e.get("reason")) - except Exception: # noqa: BLE001 — any non-JSON body (an HTML error page from a proxy) + # 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 "" return reasons or "" 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 0caa190f..e13006cb 100644 --- a/backend/ruff.toml +++ b/backend/ruff.toml @@ -19,9 +19,11 @@ line-length = 100 # 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`) and BLE001 (blind `except Exception`) are NOT here yet: 5 and 18 sites are -# outstanding, and each is a judgement about one handler — E22.5 S3 rules on them and turns the two -# rules on in the same commit. A rule enabled ahead of that work is a rule enabled with 23 blanket -# `noqa`s, which is worse than no rule. -extend-select = ["LOG", "G", "T20", "TRY400", "TRY401", "S112"] +# S110 — `except: pass`, the same thing outside one +# BLE001 — a blind `except Exception`. Every one that remains carries `# noqa: BLE001 — `, +# 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: `. 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_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: ` 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}: ` — " + f"{offenders}" + )