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}" + )