From 89c77ae6b5eecc97ead4262083dac4136e2cb35f Mon Sep 17 00:00:00 2001 From: npeter83 Date: Fri, 18 Sep 2026 23:44:42 +0200 Subject: [PATCH] =?UTF-8?q?fix(logs):=20deep-review=20round=203=20?= =?UTF-8?q?=E2=80=94=20a=20failure=20nobody=20could=20record=20is=20one=20?= =?UTF-8?q?scrubbed=20line?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - The download and edit failure lines go back after their DB write: a job the write could not fail is not a failed job, and the worker's child_exit line already says it failed. - The download child's runner is the last stop before Python's hook: an escaping exception is one download.child.failed line with its chain scrubbed, then exit 1, instead of a raw stderr traceback carrying the URL. - A crash the database will not record carries its stack once, and the fail-write line has an event code. - The job's own generic-extractor name is taken out as a literal (formats.hiding), so brackets and colons in a direct link's file name no longer leak; the pattern stays as the fallback. `Downloading just the video ` is covered. - Tests: scrubbed_stack's cause, suppress, unprintable and text-format paths, the image steps' failure kinds, the watchdog error through the real _fail_running, exact poster/storyboard messages, ffmpeg skip marker. --- backend/app/downloads/backfill.py | 5 + backend/app/downloads/formats.py | 49 ++++- backend/app/downloads/pipeline.py | 108 ++++++----- backend/app/downloads/runner.py | 35 +++- backend/app/worker.py | 12 +- .../tests/test_download_failure_catalog.py | 8 +- backend/tests/test_failure_lines.py | 171 +++++++++++++++++- backend/tests/test_logs.py | 65 +++++++ backend/tests/test_ytdlp_logging.py | 35 +++- 9 files changed, 407 insertions(+), 81 deletions(-) diff --git a/backend/app/downloads/backfill.py b/backend/app/downloads/backfill.py index 47b523c7..b793a770 100644 --- a/backend/app/downloads/backfill.py +++ b/backend/app/downloads/backfill.py @@ -30,6 +30,11 @@ log = logs.get_logger(__name__) def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: """Metadata-only yt-dlp extraction, using the source adapter's client sets + options (YouTube needs the POT/player-client strategy even just to extract).""" + with formats.hiding(url): + return _extract_meta_scoped(url, adapter, asset_id) + + +def _extract_meta_scoped(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: for clients in adapter.client_sets(): opts = formats.build_ydl_opts( {}, "%(id)s.%(ext)s", lambda d: None, extra=adapter.ydl_opts_extra(clients) diff --git a/backend/app/downloads/formats.py b/backend/app/downloads/formats.py index 1180cf97..22e43f50 100644 --- a/backend/app/downloads/formats.py +++ b/backend/app/downloads/formats.py @@ -17,10 +17,15 @@ spec shape (all keys optional; defaults + browser-playability clamp applied by ` `container`/`vcodec` keys survive only so an old stored profile deserializes without error. """ +import contextlib +import contextvars import hashlib import json import logging +import os import re +import urllib.parse +from collections.abc import Iterator from app import logs @@ -38,28 +43,60 @@ _URL_RE = re.compile(r"https?://([^/\s]+)\S*") # after it is what `_PATH_RE` takes out. _ID_PREFIX_RE = re.compile(r"(\[[\w:.-]+\] )(?!Destination:)[^\s:\[\]]+:") # The generic extractor's "id" is the URL's basename, percent-DECODED: `My%20Holiday.mp4` is -# `My Holiday` — spaces and all, which the pattern above stops at. Only this extractor: every -# other one names a site id, and letting the prefix run to `: ` everywhere would take the words -# out of lines like `[VideoConvertor] Converting video from webm to mp4; Destination: …`. +# `My Holiday` — spaces, brackets, colons and all, which no pattern can bound (`Our Trip: Day 1` +# ends at which `: `?). The job knows its own URL, so the exact name is taken out as a literal +# (`hiding`). This pattern is the fallback for a line logged outside that scope: up to the first +# `: `. Only this extractor: every other one names a site id, and letting the prefix run to `: ` +# everywhere would take the words out of lines like `[VideoConvertor] Converting …; Destination:`. _GENERIC_ID_RE = re.compile(r"(\[generic\] )(?!Destination:)[^\[\]\n]+?:(?= |$)", re.M) # `[youtube:tab] Playlist : Downloading 5 items` — the title is not an id, and has spaces. _PLAYLIST_TITLE_RE = re.compile(r"(\] Playlist ).+?(?=: Downloading )") # `[download] Finished downloading playlist: <title>`, `[download] Downloading playlist: <title>`, # `… Skipping already downloaded playlist: <title>` — the title runs to the end of the line. _TITLE_TAIL_RE = re.compile(r"(playlist: |\[download\] Downloading \w+: ).*", re.I) -# An id quoted mid-sentence, not as a prefix. -_BARE_ID_RE = re.compile(r"((?:subtitles not available for|Downloading just video) )[^\s,;]+") +# An id quoted mid-sentence, not as a prefix: `… not available for <id>`, and `--no-playlist`'s +# `Downloading just the video <id>` (`_yes_playlist`) / `Downloading just video <id>` (multifeed). +_BARE_ID_RE = re.compile( + r"((?:subtitles not available for|Downloading just (?:the )?\w+) )[^\s,;]+" +) # Two segments or more, and not glued to a word: `www.youtube.com/…` is what the URL pattern # leaves behind, and it must survive this one. _PATH_RE = re.compile(r"(?<![\w.…])/(?:[^/\s\"']+/)+[^/\s\"']*") +_HIDDEN: contextvars.ContextVar[tuple[str, ...]] = contextvars.ContextVar( + "formats_hidden", default=() +) + + +def generic_id(url: str) -> str: + """The name yt-dlp's generic extractor gives a URL: its basename, extension off, percent- + decoded — `InfoExtractor._generic_id` (2026.07.04), pinned against it in the tests.""" + return urllib.parse.unquote(os.path.splitext(url.rstrip("/").split("/")[-1])[0]) + + +@contextlib.contextmanager +def hiding(url: str | None) -> Iterator[None]: + """For the work on one URL: `log_safe` also takes out the name yt-dlp's generic extractor + gives it, exactly, where yt-dlp puts it (`[generic] <name>:`). A context variable, so it + holds for yt-dlp's logger calls too — they run on the same thread as the extraction.""" + name = generic_id(url) if url else "" + token = _HIDDEN.set((*_HIDDEN.get(), name) if name else _HIDDEN.get()) + try: + yield + finally: + _HIDDEN.reset(token) + + def log_safe(text: object) -> str: """yt-dlp's text (its own lines, or a DownloadError's message) with the parts that name a person's download taken out. Every log line that carries yt-dlp's words goes through here, not just the adapter's: yt-dlp raises the same text it has just logged, so a line that skipped it would put back one line later exactly what the adapter took out.""" - text = _URL_RE.sub(lambda m: f"{m.group(1)}/…", str(text)) + text = str(text) + for name in _HIDDEN.get(): + text = text.replace(f"[generic] {name}:", "[generic] …:") + text = _URL_RE.sub(lambda m: f"{m.group(1)}/…", text) text = _ID_PREFIX_RE.sub(r"\1…:", text) text = _GENERIC_ID_RE.sub(r"\1…:", text) text = _PLAYLIST_TITLE_RE.sub(r"\1…", text) diff --git a/backend/app/downloads/pipeline.py b/backend/app/downloads/pipeline.py index 39006d64..d61e99b6 100644 --- a/backend/app/downloads/pipeline.py +++ b/backend/app/downloads/pipeline.py @@ -654,30 +654,28 @@ def _download( diagnosis = dlerrors.diagnose(msg, url=url, cookie_attached=cookiefile is not None) # SEC-12: redact a transport-level readout for user-supplied URLs (see user_error_text). msg = dlerrors.user_error_text(source_kind, msg, diagnosis.code) - # The line goes out whether or not the write below succeeds: when the database is what - # failed, that write fails too, and the failure would otherwise leave no line at all. - try: - with SessionLocal() as db: - asset = db.get(MediaAsset, asset_id) - if asset: - asset.status = "error" - asset.error = msg - # Atomic fail: only while still running, so a route-set cancel/pause is never - # overwritten with `error` (error also holds the asset → would re-open the - # double-release class). - service.finalize_if_running( - db, - job_id, - status=JobStatus.ERROR, - error=msg, - error_code=diagnosis.code, - error_detail=diagnosis.detail, - phase=None, - ) - db.commit() - finally: - # silent-ok: not silent — `_log_download_failed` is the report. - _log_download_failed(job_id, msg, diagnosis.code, exc) + with SessionLocal() as db: + asset = db.get(MediaAsset, asset_id) + if asset: + asset.status = "error" + asset.error = msg + # Atomic fail: only while still running, so a route-set cancel/pause is never + # overwritten with `error` (error also holds the asset → would re-open the + # double-release class). + service.finalize_if_running( + db, + job_id, + status=JobStatus.ERROR, + error=msg, + error_code=diagnosis.code, + error_detail=diagnosis.detail, + phase=None, + ) + db.commit() + # After the write: a job the write could not fail is not a failed job. When it raises, + # the runner reports this failure with it (`runner._run`) and the worker fails the job. + # silent-ok: not silent — `_log_download_failed` is the report. + _log_download_failed(job_id, msg, diagnosis.code, exc) finally: # Unlink the decrypted cookie file explicitly (the rmtree below removes the whole staging # tree too, but never leave a plaintext session cookie on disk a moment longer than needed). @@ -729,40 +727,38 @@ def _fail_edit(job_id: int, asset_id: int, msg: str, exc: BaseException | None = where its line and its event code live. `exc` is the exception when there was one. Its traceback goes with the line unless the message already tells it all (`_failure_stack`). - The line goes out whether or not the write succeeds (see the download error path).""" - try: - with SessionLocal() as db: - asset = db.get(MediaAsset, asset_id) - if asset: - asset.status = "error" - asset.error = msg - # Atomic fail: only while still running (see the download error path). - service.finalize_if_running( - db, - job_id, - status=JobStatus.ERROR, - error=msg, - error_code=dlerrors.classify(msg), - phase=None, - ) - db.commit() - finally: - # `msg` is the user's copy; ffmpeg's stderr tail in it can name the source file, whose - # path is built from the channel and the title. - log.warning( - "edit job %s failed: %s", + Logged after the write, as on the download error path.""" + with SessionLocal() as db: + asset = db.get(MediaAsset, asset_id) + if asset: + asset.status = "error" + asset.error = msg + # Atomic fail: only while still running (see the download error path). + service.finalize_if_running( + db, job_id, - formats.log_safe(msg), - extra={ - **logs.event( - "edit.job.failed", - job_id=job_id, - asset_id=asset_id, - **({"error_type": type(exc).__name__} if exc is not None else {}), - ), - **(_failure_stack(exc) if exc is not None else {}), - }, + status=JobStatus.ERROR, + error=msg, + error_code=dlerrors.classify(msg), + phase=None, ) + db.commit() + # `msg` is the user's copy; ffmpeg's stderr tail in it can name the source file, whose path is + # built from the channel and the title. + log.warning( + "edit job %s failed: %s", + job_id, + formats.log_safe(msg), + extra={ + **logs.event( + "edit.job.failed", + job_id=job_id, + asset_id=asset_id, + **({"error_type": type(exc).__name__} if exc is not None else {}), + ), + **(_failure_stack(exc) if exc is not None else {}), + }, + ) def _process_edit(job_id: int, asset_id: int) -> None: diff --git a/backend/app/downloads/runner.py b/backend/app/downloads/runner.py index 37c08f73..ac87b6c1 100644 --- a/backend/app/downloads/runner.py +++ b/backend/app/downloads/runner.py @@ -21,6 +21,7 @@ from app import logsink from app.config import settings from app.db import SessionLocal from app.downloads import edit as editmod +from app.downloads import formats from app.models import DownloadJob log = logs.get_logger(__name__) @@ -81,14 +82,40 @@ def main() -> None: if asset_id is None: return + _run(job_id, asset_id, job_kind, source_kind, source_ref, spec, user_id) + + +def _run(job_id, asset_id, job_kind, source_kind, source_ref, spec, user_id) -> None: + """Run the job, and be the last stop before Python's own exception hook. + + What gets past the pipeline is a failure it could not even record (the database refused the + write that fails the job). Python's hook would print it to stderr raw — and its context is the + download's own failure, whose text is the URL or ffmpeg's stderr naming the file. Here it is + one line with the whole chain scrubbed; the non-zero exit then has the worker fail the job + (`cause=child_exit`).""" # Imported here (not at module top) so the child pays the yt-dlp import cost only when it has # real work, and to keep the import graph obvious: runner is a thin entry over the pipeline. from app.downloads.pipeline import _download, _process_edit - if job_kind == "edit": - _process_edit(job_id, asset_id) - else: - _download(job_id, asset_id, source_kind, source_ref, spec, user_id) + with formats.hiding(source_ref): + try: + if job_kind == "edit": + _process_edit(job_id, asset_id) + else: + _download(job_id, asset_id, source_kind, source_ref, spec, user_id) + except Exception as exc: # noqa: BLE001 — whatever it is, it is reported here or raw + # noqa TRY400: the stack goes with it scrubbed (`scrubbed_stack`); `exc_info` is raw. + log.error( # noqa: TRY400 + "the download child for job %s failed", + job_id, + extra={ + **logs.event( + "download.child.failed", job_id=job_id, error_type=type(exc).__name__ + ), + **logs.scrubbed_stack(exc, formats.log_safe), + }, + ) + raise SystemExit(1) from None if __name__ == "__main__": diff --git a/backend/app/worker.py b/backend/app/worker.py index 77648159..1aac2d5a 100644 --- a/backend/app/worker.py +++ b/backend/app/worker.py @@ -329,10 +329,14 @@ def _report_worker_error(job_id: int, exc: Exception, cause: str, fail: Callable already stopped it (a cancel that landed first is not a failure, `_fail_running`). The line goes out even when failing the job raises (the database is down): as - `download.worker.error`, since the job was not failed, and the raise goes on to the caller.""" + `download.worker.error`, since the job was not failed, and the raise goes on to the caller — + without `exc` as its context, which this line has already carried with its stack.""" failed = False try: failed = fail() + except BaseException as write_error: + write_error.__suppress_context__ = True + raise finally: log.error( "job %s: worker error (%s)", @@ -599,7 +603,11 @@ def _worker_loop(idx: int) -> None: # re-raise. Failing the job hit the database, and letting that out would end this # worker thread for good; boot recovery settles a job left `running`. except Exception: # noqa: BLE001 - log.exception("could not fail job %s after its crash", job_id) + log.exception( + "could not fail job %s after its crash", + job_id, + extra=logs.event("download.worker.fail_write_failed", job_id=job_id), + ) def main() -> None: diff --git a/backend/tests/test_download_failure_catalog.py b/backend/tests/test_download_failure_catalog.py index e56f15bc..ae7341ab 100644 --- a/backend/tests/test_download_failure_catalog.py +++ b/backend/tests/test_download_failure_catalog.py @@ -125,9 +125,9 @@ def test_the_download_child_knows_the_cookie_went_with_it(db, monkeypatch, tmp_p assert (job.error_code, job.error_detail) == ("login_required", "facebook.cookie_rejected") -def test_the_failure_line_goes_out_even_when_its_write_fails(db, monkeypatch, tmp_path): - """The database is often what failed; the write of the failure then fails too, and the line - that says so must not go down with it.""" +def test_a_failure_the_database_would_not_record_is_not_claimed(db, monkeypatch, tmp_path): + """The job is still `running`: the runner reports this with the write's error, and the worker + fails the job. A `download.job.failed` here as well would be a second line, and a false one.""" u = _user(db, "fb-dbdown@example.com") a, j = _asset_and_job(db, u, sig="dbdown", asset_status="downloading", job_status="running") _fail_the_child(monkeypatch, tmp_path, cookie=False) @@ -141,7 +141,7 @@ def test_the_failure_line_goes_out_even_when_its_write_fails(db, monkeypatch, tm with pytest.raises(ConnectionError): pipeline._download(j.id, a.id, "url", _REEL, {}, u.id) - assert said == [j.id] + assert said == [] def test_a_job_meeting_a_failed_shared_asset_gets_the_same_explanation(db): diff --git a/backend/tests/test_failure_lines.py b/backend/tests/test_failure_lines.py index c5332f0f..80b1f6b4 100644 --- a/backend/tests/test_failure_lines.py +++ b/backend/tests/test_failure_lines.py @@ -8,6 +8,9 @@ same edit failure twice, a warning per segment request, per settings read). import json import logging +import re +import shutil +import subprocess from pathlib import Path from types import SimpleNamespace @@ -220,9 +223,9 @@ def test_an_edit_that_ffmpeg_refused_names_no_file_and_carries_no_stack(sink, fi assert "exc" not in line -def test_an_edit_failure_is_reported_even_when_its_write_fails(sink, monkeypatch): - """The database is often what failed; then the write fails too, and the line must not go - down with it.""" +def test_an_edit_the_database_would_not_fail_is_not_reported_as_failed(sink, monkeypatch): + """The job is still `running`: the runner reports this failure with the write's, and the + worker fails the job (`child_exit`). A line here as well would be a second, and a false one.""" class _Down: def __enter__(self): @@ -235,7 +238,7 @@ def test_an_edit_failure_is_reported_even_when_its_write_fails(sink, monkeypatch with pytest.raises(ConnectionError): pipeline._fail_edit(9, 3, "boom", KeyError("x")) - assert len(sink.events("edit.job.failed")) == 1 + assert sink.events("edit.job.failed") == [] class _EditDb(_NoDb): @@ -371,6 +374,31 @@ def test_the_metadata_backfill_names_the_asset_and_not_the_download(sink, monkey assert lines and all("dQw4w9WgXcQ" not in json.dumps(o) for o in lines) +def test_the_metadata_backfill_takes_out_a_generic_name_whatever_it_holds(sink, monkeypatch): + from app.downloads import adapters, backfill + + url = "https://example.org/v/Our%20Trip%3A%20Day%201.mp4" + + class _Refusing: + def __init__(self, opts): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def extract_info(self, target, download): + raise yt_dlp.utils.DownloadError("ERROR: [generic] Our Trip: Day 1: Unable to download") + + monkeypatch.setattr(backfill.yt_dlp, "YoutubeDL", _Refusing) + assert backfill._extract_meta(url, adapters.SourceAdapter(), 11) is None + + lines = [o for o in sink.objects() if "meta extract failed" in o["msg"]] + assert lines and all("Day 1" not in json.dumps(o) for o in lines) + + # --- a repeating failure, once ------------------------------------------------------------------ def test_a_stale_setting_is_reported_once_not_on_every_read(sink, monkeypatch): spec = next(s for s in sysconfig.SPECS if s.type == "int") @@ -446,6 +474,7 @@ def test_a_retried_attempt_names_the_host_and_not_the_video(sink, monkeypatch, t assert "dQw4w9WgXcQ" not in json.dumps(line) +@pytest.mark.skipif(shutil.which("ffmpeg") is None, reason="ffmpeg not available") def test_a_failed_poster_or_storyboard_names_no_file(sink, tmp_path): """ffmpeg's CalledProcessError quotes its argv, and the source path in it is built from the channel and the title.""" @@ -459,7 +488,135 @@ def test_a_failed_poster_or_storyboard_names_no_file(sink, tmp_path): assert editmod.ensure_poster(asset, str(tmp_path)) is None assert editmod.ensure_storyboard(asset, str(tmp_path)) is None - lines = [o for o in sink.objects() if "gen skipped" in o["msg"]] + lines = [o["msg"] for o in sink.objects() if "gen skipped" in o["msg"]] + # The whole message: a long tmp root would push a leaked argv's path past any length cut. assert len(lines) == 2 - assert all("Some_Channel" not in json.dumps(o) for o in lines) - assert all("CalledProcessError" in o["msg"] for o in lines) + assert all( + re.fullmatch(r"\w+ gen skipped for asset 3: CalledProcessError \d+", m) for m in lines + ) + + +@pytest.mark.parametrize( + "err", + [ + subprocess.TimeoutExpired( + ["ffmpeg", "-i", "/downloads/Some_Channel/A_Private_Title.mp4"], 30 + ), + FileNotFoundError(2, "No such file", "/downloads/Some_Channel/A_Private_Title.jpg"), + subprocess.CalledProcessError(1, ["ffmpeg", "-i", "/downloads/Some_Channel/x.mp4"]), + ], + ids=lambda e: type(e).__name__, +) +def test_an_image_step_failure_is_its_kind_and_nothing_it_quotes(err): + from app.downloads import edit as editmod + + code = getattr(err, "returncode", None) + assert editmod._step_failure(err) == " ".join( + [type(err).__name__, *([str(code)] if code is not None else [])] + ) + + +def test_a_thumbnail_that_cannot_be_copied_names_no_file(sink, monkeypatch, tmp_path): + from app.downloads import edit as editmod + + src = tmp_path / "thumb.jpg" + src.write_bytes(b"\xff\xd8\xff rest") + + def refuse(a, b): + raise PermissionError( + 13, "Permission denied", "/downloads/Some_Channel/A_Private_Title.jpg" + ) + + monkeypatch.setattr(editmod.shutil, "copyfile", refuse) + assert editmod.thumbnail_to_jpg(src, tmp_path / "out.jpg") is None + + (line,) = [o for o in sink.objects() if "thumbnail copy failed" in o["msg"]] + assert "Some_Channel" not in json.dumps(line) + + +# --- the child's last stop ------------------------------------------------------------------------ +def test_a_failure_the_child_cannot_record_is_one_scrubbed_line_and_a_non_zero_exit( + sink, monkeypatch +): + """The pipeline's failure write was refused. Python's own hook would print the chain raw — + and its context is the download's failure, the URL in it. The worker fails the job on the + exit code (`child_exit`), so this line does not claim the job failed.""" + from app.downloads import runner + + url = "https://example.org/v/Our%20Trip%3A%20Day%201.mp4" + text = f"ERROR: [generic] Our Trip: Day 1: Unable to download webpage ({url})" + + def download(*a): + try: + raise yt_dlp.utils.DownloadError(text) + except yt_dlp.utils.DownloadError: + raise ConnectionError("the database went away") # noqa: B904 + + monkeypatch.setattr(pipeline, "_download", download) + with pytest.raises(SystemExit) as exited: + runner._run(5, 7, "download", "url", url, {}, 1) + + assert exited.value.code == 1 + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert line["event"] == "download.child.failed" + assert "Unable to download webpage" in line["exc"] + # "Day 1" too: the fallback pattern alone stops at the first `: ` and leaves it. + assert "Trip" not in json.dumps(line) and "Day 1" not in json.dumps(line) + + +def test_a_crash_the_database_will_not_record_carries_its_stack_once(monkeypatch, sink): + claims = iter([42]) + + def claim(): + job = next(claims, None) + if job is None: + worker._stop.set() + return job + + def crash(job_id): + raise RuntimeError("the one crash") + + def db_down(*a, **k): + raise ConnectionError("the database went away") + + monkeypatch.setattr(worker, "_claim_job", claim) + monkeypatch.setattr(worker, "_process_job", crash) + monkeypatch.setattr(worker, "_fail_running", db_down) + monkeypatch.setattr(worker.settings, "download_poll_seconds", 0) + worker._stop.clear() + try: + worker._worker_loop(0) + finally: + worker._stop.clear() + + stacks = [o["exc"] for o in sink.objects() if "exc" in o] + assert sum("the one crash" in s for s in stacks) == 1 + (write,) = sink.events("download.worker.fail_write_failed") + assert "the database went away" in write["exc"] + + +def test_a_watchdog_error_on_a_job_it_failed_is_that_jobs_failure_line( + sink, finalized, monkeypatch +): + """Through the real `_fail_after_kill` → `_fail_running`: the verdict it returns picks the + event, so a lost `return` would log every such failure as a mere worker error.""" + + class _Alive: + pid = 4242 + returncode = None + + def wait(self, timeout=None): + raise subprocess.TimeoutExpired("child", timeout or 0) + + def broken(job_id): + raise KeyError("a watchdog bug") + + monkeypatch.setattr(worker, "_spawn_download_child", lambda job_id: _Alive()) + monkeypatch.setattr(worker, "_job_liveness", broken) + monkeypatch.setattr(worker, "_stop_and_free", lambda *a: None) + + worker._run_supervised(42, 7) + + (line,) = [o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")] + assert (line["event"], line["attrs"]["cause"]) == ("download.job.failed", "supervisor_error") + assert "a watchdog bug" in line["exc"] diff --git a/backend/tests/test_logs.py b/backend/tests/test_logs.py index ae8b883e..556db984 100644 --- a/backend/tests/test_logs.py +++ b/backend/tests/test_logs.py @@ -318,3 +318,68 @@ def test_a_failing_request_is_logged_by_status_and_an_unhandled_error_is_logged_ assert payload["level"] == "ERROR" assert payload["event"] == "http.request" assert "RuntimeError" in payload["exc"] + + +# --- a stack whose messages are data (`logs.scrubbed_stack`) ----------------------------------- +def _upper(exc: BaseException) -> str: + return str(exc).upper() + + +def _raised(make): + try: + make() + except Exception as exc: # noqa: BLE001 — whatever the case raised is the case + return exc + raise AssertionError("the case did not raise") + + +def test_a_raise_from_is_printed_as_its_direct_cause(): + def make(): + try: + raise KeyError("inner") + except KeyError as inner: + raise ValueError("outer") from inner + + stack = logs.scrubbed_stack(_raised(make), _upper)["scrubbed_stack"] + assert "The above exception was the direct cause" in stack + assert "During handling" not in stack + assert "'INNER'" in stack and "OUTER" in stack + + +def test_a_raise_from_none_hides_the_link_its_author_hid(): + def make(): + try: + raise KeyError("hidden") + except KeyError: + raise ValueError("shown") from None + + stack = logs.scrubbed_stack(_raised(make), _upper)["scrubbed_stack"] + assert "HIDDEN" not in stack and "SHOWN" in stack + + +def test_a_chain_that_loops_back_ends(): + a, b = ValueError("a"), ValueError("b") + a.__context__, b.__context__ = b, a + assert "A" in logs.scrubbed_stack(a, _upper)["scrubbed_stack"] + + +def test_a_message_that_cannot_be_rendered_does_not_fail_the_report(): + def refuse(exc): + raise RuntimeError("no") + + assert ( + logs.scrubbed_stack(ValueError("x"), refuse)["scrubbed_stack"] + == "ValueError: <unprintable>" + ) + + +def test_the_text_format_carries_the_scrubbed_stack_too(): + title = "a private title" # a variable: a frame prints its source line, which is code + exc = ValueError(title) + record = logging.LogRecord("siftlode.x", logging.WARNING, __file__, 1, "failed", None, None) + for key, value in logs.scrubbed_stack(exc, lambda e: "…").items(): + setattr(record, key, value) + + line = logs.TextFormatter().format(record) + assert "ValueError: …" in line and "private" not in line + assert "scrubbed_stack" not in line # the stack, not an attribute diff --git a/backend/tests/test_ytdlp_logging.py b/backend/tests/test_ytdlp_logging.py index afee4519..02950256 100644 --- a/backend/tests/test_ytdlp_logging.py +++ b/backend/tests/test_ytdlp_logging.py @@ -134,9 +134,15 @@ def test_the_source_url_does_not_travel_with_the_explanation(sink): "hu subtitles not available for …", "dQw4w9WgXcQ", ), + # `watch?v=…&list=…` under `noplaylist` (`_yes_playlist`), and the multifeed shape. ( - "[youtube:tab] Downloading just video dQw4w9WgXcQ because of --no-playlist", - "[youtube:tab] Downloading just video … because of --no-playlist", + "[youtube:tab] Downloading just the video dQw4w9WgXcQ because of --no-playlist", + "[youtube:tab] Downloading just the video … because of --no-playlist", + "dQw4w9WgXcQ", + ), + ( + "[youtube] Downloading just video dQw4w9WgXcQ because of --no-playlist", + "[youtube] Downloading just video … because of --no-playlist", "dQw4w9WgXcQ", ), # `Destination` is yt-dlp's word, not an id; the path after it is built from the title. @@ -155,6 +161,31 @@ def test_what_names_the_download_comes_out_of_real_ytdlp_shapes(sink, line, kept assert gone not in json.dumps(obj) +@pytest.mark.parametrize( + ("url", "name"), + [ + ("https://example.org/v/Wedding%20%5B2024%5D.mp4", "Wedding [2024]"), + ("https://example.org/v/Our%20Trip%3A%20Day%201.mp4", "Our Trip: Day 1"), + ], +) +def test_the_jobs_own_generic_name_is_taken_out_whatever_it_holds(url, name): + """Brackets and `: ` bound no pattern; the job knows its URL, so the exact name goes.""" + line = f"ERROR: [generic] {name}: Unable to download webpage: HTTP Error 404: Not Found" + + assert formats.generic_id(url) == name + with formats.hiding(url): + assert formats.log_safe(line) == ( + "ERROR: [generic] …: Unable to download webpage: HTTP Error 404: Not Found" + ) + + +def test_the_generic_name_is_yt_dlps_own(): + from yt_dlp.extractor.common import InfoExtractor + + for url in ("https://x.org/a/My%20Holiday.mp4", "https://x.org/a/clip/", "https://x.org/b"): + assert formats.generic_id(url) == InfoExtractor._generic_id(url) + + def test_a_download_error_is_scrubbed_the_same_way_wherever_it_is_logged(): """yt-dlp raises the text it has just logged, and the pipeline logs the exception again one line later (`download.job.failed`). The same scrub, or that line puts the URL back."""