diff --git a/backend/app/downloads/formats.py b/backend/app/downloads/formats.py index f9c2202b..ea87f722 100644 --- a/backend/app/downloads/formats.py +++ b/backend/app/downloads/formats.py @@ -19,11 +19,57 @@ spec shape (all keys optional; defaults + browser-playability clamp applied by ` import hashlib import json +import logging +import re from app import logs log = logs.get_logger(__name__) +# yt-dlp puts the full source URL in most of its lines, and a source URL is a row of someone's +# download history. The job id is already on every line (`logs.set_job` in the download child), so +# the URL adds nothing an operator needs and plenty they should not keep. +_URL_RE = re.compile(r"https?://([^/\s]+)\S*") + + +class _YdlLog: + """yt-dlp's logger protocol, pointed at ours. + + Without it yt-dlp explains itself to nobody: `quiet` sends its output to a stdout we do not + read, so "Requested format is not available", a signature-extraction failure or a POT refusal + reached us only as whatever text ended up in the raised exception. Measured against yt-dlp + 2026.07.04: with `logger` set it calls `debug` for extraction and progress lines and + `warning`/`error` for the rest, and `quiet`/`no_warnings` do NOT gate those calls. + + `debug` goes to TRACE — it is several lines per second during a download, and TRACE is the + level a user turns on for their own session. Everything else keeps its level.""" + + @staticmethod + def _clean(msg: str) -> str: + return _URL_RE.sub(lambda m: f"{m.group(1)}/…", str(msg)) + + def _emit(self, level: int, msg: str) -> None: + # The line goes as an ARGUMENT, not as the format string. yt-dlp writes progress as + # `[download] 53.2% of 12.00MiB`, and while stdlib logging only applies `%` formatting to + # a record that has args, this way the question never arises — and it is the shape ruff's + # `G` rules ask for. + log.log(level, "%s", self._clean(msg), extra=logs.event("download.ytdlp")) + + def debug(self, msg): + self._emit(logs.TRACE, msg) + + def info(self, msg): + self._emit(logging.DEBUG, msg) + + def warning(self, msg): + self._emit(logging.WARNING, msg) + + def error(self, msg): + self._emit(logging.ERROR, msg) + + +_YDL_LOG = _YdlLog() + # Fields that affect the produced file — and therefore the cache identity. _SIG_KEYS = ( "mode", @@ -191,6 +237,12 @@ def build_ydl_opts( if extra: opts.update(extra) + # With a logger attached, `quiet` and `no_warnings` stop deciding whether yt-dlp explains itself + # and only decide where — so both stay on above and the explanation comes here instead of to a + # stdout nothing reads. AFTER the adapter merge, like `cookiefile` and the size cap: an adapter + # must not be able to silence the one account of what went wrong that a failed job leaves. + opts["logger"] = _YDL_LOG + # SEC-13: hard ceiling on a single download. AFTER the adapter merge, for the same reason # `cookiefile` is — a source adapter must not be able to raise a limit the quota layer set. # diff --git a/backend/app/downloads/pipeline.py b/backend/app/downloads/pipeline.py index e07d4300..8353d5f0 100644 --- a/backend/app/downloads/pipeline.py +++ b/backend/app/downloads/pipeline.py @@ -603,13 +603,22 @@ def _download( db.commit() if finalized: _notify_download_done(db, owner_id, meta.title, job_id, kind="download") - log.info("job %s done: %s", job_id, rel) + log.info( + "job %s done: %s", + job_id, + rel, + extra=logs.event("download.job.done", job_id=job_id), + ) except (_Aborted, editmod.EditAborted): # Paused/canceled mid-download or mid-transcode: free the asset for a later retry; keep the # job's status (the route set it to paused/canceled). ref_count is adjusted by the route. _reset_asset_pending(asset_id) - log.info("job %s aborted (pause/cancel)", job_id) + log.info( + "job %s aborted (pause/cancel)", + job_id, + extra=logs.event("download.job.aborted", job_id=job_id), + ) except _OwnerRefused as exc: # Fail this job only. The asset is never marked `error`; it goes back to `pending` (below), # so another user's job for the same video is claimed and downloaded normally instead of @@ -630,7 +639,12 @@ def _download( # it, and this one must already be out of the way. (The staging tree is still torn down in # `finally` below — the same narrow window the pause/cancel path above has always had.) _reset_asset_pending(asset_id) - log.info("job %s refused for its owner: %s", job_id, msg) + log.info( + "job %s refused for its owner: %s", + job_id, + msg, + extra=logs.event("download.job.refused", job_id=job_id), + ) except Exception as exc: # noqa: BLE001 — surface any failure to the user, keep worker alive msg = str(exc)[:500] # The catalog needs the link and whether the user's cookie went with it: the same yt-dlp @@ -777,12 +791,21 @@ def _process_edit(job_id: int, asset_id: int) -> None: db.commit() if finalized: _notify_download_done(db, owner_id, dl_title, job_id, kind="edit") - log.info("edit job %s done: %s", job_id, rel) + log.info( + "edit job %s done: %s", + job_id, + rel, + extra=logs.event("edit.job.done", job_id=job_id), + ) except editmod.EditAborted: # Paused/canceled mid-encode: free the asset for a later retry (ref_count is the route's job). _reset_asset_pending(asset_id) - log.info("edit job %s aborted (pause/cancel)", job_id) + log.info( + "edit job %s aborted (pause/cancel)", + job_id, + extra=logs.event("edit.job.aborted", job_id=job_id), + ) except Exception as exc: # noqa: BLE001 — surface the failure, keep the worker alive # `_fail_edit` 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. diff --git a/backend/app/plex/stream.py b/backend/app/plex/stream.py index dcf92651..e4b5934e 100644 --- a/backend/app/plex/stream.py +++ b/backend/app/plex/stream.py @@ -644,6 +644,13 @@ def _enforce_cap(cap: int) -> None: if len(tx) <= cap: return for key, s in sorted(tx, key=lambda kv: kv[1].last_access)[: len(tx) - cap]: + # Somebody's playback stops here. The route turns the missing session into a retryable + # 404 and the player restarts at the playhead, so from the server nothing failed — and + # "my film keeps rebuffering" has no other explanation anywhere. + log.info( + "a transcode session was dropped to stay under the cap", + extra=logs.event("plex.stream.session_culled", key=key, cap=cap, sessions=len(tx)), + ) _kill(s) _sessions.pop(key, None) @@ -746,6 +753,21 @@ def start_session( tonemap=tonemap, ) _sessions[key] = s + # The one line that says which pipeline a session actually got. Everything downstream + # — the cap, the HW→SW fallback, the subtitle offset — is about this choice, and until + # now it was only inferable from the ffmpeg command nobody keeps. + log.info( + "an HLS session started", + extra=logs.event( + "plex.stream.session_started", + key=key, + transcode=transcode, + hw=hw, + tonemap=tonemap, + variants=len(variants or ()), + start_s=round(start_s, 1), + ), + ) # Admin-configurable concurrency cap (Configuration → Plex → Max concurrent transcodes); # at least 1 so playback can't be capped to zero. _enforce_cap(max(1, sysconfig.get_int(db, "plex_max_transcodes"))) @@ -764,7 +786,8 @@ def start_session( # ONE lock in _spawn, so we can never tear down the newer session. s.hw is now False, so the route # honestly reports "CPU" and the player's Preparing-stream state stays correct. log.warning( - "plex transcode: HW session produced no segments — falling back to software key=%s", key + "the hardware transcode produced no segments; falling back to software", + extra=logs.event("plex.stream.hw_fallback", key=key), ) respawned = _spawn(False, False, replace_only=s) if respawned is None: diff --git a/backend/app/routes/search.py b/backend/app/routes/search.py index 12bf35b9..7cf66d12 100644 --- a/backend/app/routes/search.py +++ b/backend/app/routes/search.py @@ -249,12 +249,22 @@ def search_youtube( daily_limit = sysconfig.get_int(db, "search_daily_limit_per_user") used = quota.actions_today(db, user.id, quota.QuotaAction.VIDEOS_SEARCH) if used >= daily_limit: + # The 429 is in the request line either way; which of the two caps produced it is not, and + # they are answered by different things — this one by tomorrow, the other by the admin. + log.info( + "a live search was refused: the per-user daily cap is spent", + extra=logs.event("search.refused", reason="daily_cap", limit=daily_limit), + ) raise HTTPException( status_code=429, detail=f"You've reached today's YouTube search limit ({daily_limit}). Try again tomorrow.", ) # The 100-unit budget pre-check only applies to the API source. if source == "api" and not quota.can_spend(db, SEARCH_COST): + log.info( + "a live search was refused: the shared YouTube budget is spent", + extra=logs.event("search.refused", reason="shared_quota", cost=SEARCH_COST), + ) raise HTTPException( status_code=429, detail="The shared YouTube quota for today is used up. Try again tomorrow.", diff --git a/backend/tests/test_ytdlp_logging.py b/backend/tests/test_ytdlp_logging.py new file mode 100644 index 00000000..b6ac4421 --- /dev/null +++ b/backend/tests/test_ytdlp_logging.py @@ -0,0 +1,108 @@ +"""E22.5 S4 — yt-dlp explains itself to our log, not to a stdout nobody reads. + +`quiet: True` was doing more than quieting: with no `logger`, yt-dlp's whole account of a download +went to the child process's stdout, so "Requested format is not available", a signature-extraction +failure or a POT refusal reached us only as whatever text happened to end up in the raised +exception. A failed download's real reason was routinely one line the app never kept. + +Measured against yt-dlp 2026.07.04 (the pinned version): with `logger` set, yt-dlp calls `debug` +for its extraction and progress lines and `warning`/`error` for the rest, and neither `quiet` nor +`no_warnings` gates those calls. The cases below pin what we do with them. +""" + +import json +import logging + +import pytest + +from app import logs +from app.downloads import formats + +URL = "https://www.youtube.com/watch?v=dQw4w9WgXcQ&list=PLsomething" + + +class _Sink(logging.Handler): + """The stdout handler's own filter and formatter, so a case sees the bytes a deployment writes.""" + + def __init__(self): + super().__init__(level=logging.NOTSET) + self.lines: list[str] = [] + self.setFormatter(logs.JsonFormatter()) + self.addFilter(logs.ContextFilter()) + + def emit(self, record): + self.lines.append(self.format(record)) + + def objects(self) -> list[dict]: + return [json.loads(line) for line in self.lines] + + +@pytest.fixture +def sink(): + logger = logging.getLogger("siftlode") + handler = _Sink() + previous = logger.level + logger.addHandler(handler) + logger.setLevel(logs.TRACE) + try: + yield handler + finally: + logger.removeHandler(handler) + logger.setLevel(previous) + + +@pytest.mark.parametrize( + ("method", "level"), + [ + # Several lines per second during a download, and TRACE is the level a user turns on for + # their own session — so the noisy half is exactly the half the consent gates. + ("debug", "TRACE"), + ("info", "DEBUG"), + ("warning", "WARNING"), + ("error", "ERROR"), + ], +) +def test_each_ytdlp_level_lands_where_it_belongs(sink, method, level): + getattr(formats._YDL_LOG, method)("something happened") + + (line,) = sink.objects() + assert line["level"] == level + assert line["event"] == "download.ytdlp" + assert "something happened" in line["msg"] + + +def test_the_source_url_does_not_travel_with_the_explanation(sink): + formats._YDL_LOG.error(f"ERROR: [youtube] {URL}: Requested format is not available") + + (line,) = sink.objects() + # The host survives — it is what says which extractor is failing. The rest is a row of this + # person's download history, and the job id already names the job on every one of these lines. + assert "www.youtube.com/…" in line["msg"] + assert "dQw4w9WgXcQ" not in json.dumps(line) + assert "list=PLsomething" not in json.dumps(line) + assert "Requested format is not available" in line["msg"] + + +def test_a_line_with_no_url_is_left_alone(sink): + formats._YDL_LOG.warning("nsig extraction failed: Some formats may be missing") + + (line,) = sink.objects() + assert "nsig extraction failed: Some formats may be missing" in line["msg"] + + +def test_the_download_options_carry_the_logger(): + opts = formats.build_ydl_opts({}, "%(id)s.%(ext)s", lambda d: None) + + assert opts["logger"] is formats._YDL_LOG + + +def test_a_source_adapter_cannot_silence_it(): + """`extra` is the adapter's own options (YouTube's player-client/POT strategy), merged wholesale. + The logger is set after that merge for the same reason `cookiefile` and the size cap are: an + adapter must not be able to take away the one account of what went wrong that a failed job + leaves behind.""" + opts = formats.build_ydl_opts( + {}, "%(id)s.%(ext)s", lambda d: None, extra={"logger": None, "quiet": False} + ) + + assert opts["logger"] is formats._YDL_LOG