fix(logs): deep-review round 3 — a failure nobody could record is one scrubbed line
- 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 <id>` 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.
This commit is contained in:
@@ -30,6 +30,11 @@ log = logs.get_logger(__name__)
|
|||||||
def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None:
|
def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None:
|
||||||
"""Metadata-only yt-dlp extraction, using the source adapter's client sets + options (YouTube
|
"""Metadata-only yt-dlp extraction, using the source adapter's client sets + options (YouTube
|
||||||
needs the POT/player-client strategy even just to extract)."""
|
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():
|
for clients in adapter.client_sets():
|
||||||
opts = formats.build_ydl_opts(
|
opts = formats.build_ydl_opts(
|
||||||
{}, "%(id)s.%(ext)s", lambda d: None, extra=adapter.ydl_opts_extra(clients)
|
{}, "%(id)s.%(ext)s", lambda d: None, extra=adapter.ydl_opts_extra(clients)
|
||||||
|
|||||||
@@ -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.
|
`container`/`vcodec` keys survive only so an old stored profile deserializes without error.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
|
import contextlib
|
||||||
|
import contextvars
|
||||||
import hashlib
|
import hashlib
|
||||||
import json
|
import json
|
||||||
import logging
|
import logging
|
||||||
|
import os
|
||||||
import re
|
import re
|
||||||
|
import urllib.parse
|
||||||
|
from collections.abc import Iterator
|
||||||
|
|
||||||
from app import logs
|
from app import logs
|
||||||
|
|
||||||
@@ -38,28 +43,60 @@ _URL_RE = re.compile(r"https?://([^/\s]+)\S*")
|
|||||||
# after it is what `_PATH_RE` takes out.
|
# after it is what `_PATH_RE` takes out.
|
||||||
_ID_PREFIX_RE = re.compile(r"(\[[\w:.-]+\] )(?!Destination:)[^\s:\[\]]+:")
|
_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
|
# 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
|
# `My Holiday` — spaces, brackets, colons and all, which no pattern can bound (`Our Trip: Day 1`
|
||||||
# other one names a site id, and letting the prefix run to `: ` everywhere would take the words
|
# ends at which `: `?). The job knows its own URL, so the exact name is taken out as a literal
|
||||||
# out of lines like `[VideoConvertor] Converting video from webm to mp4; Destination: …`.
|
# (`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)
|
_GENERIC_ID_RE = re.compile(r"(\[generic\] )(?!Destination:)[^\[\]\n]+?:(?= |$)", re.M)
|
||||||
# `[youtube:tab] Playlist <title>: Downloading 5 items` — the title is not an id, and has spaces.
|
# `[youtube:tab] Playlist <title>: Downloading 5 items` — the title is not an id, and has spaces.
|
||||||
_PLAYLIST_TITLE_RE = re.compile(r"(\] Playlist ).+?(?=: Downloading )")
|
_PLAYLIST_TITLE_RE = re.compile(r"(\] Playlist ).+?(?=: Downloading )")
|
||||||
# `[download] Finished downloading playlist: <title>`, `[download] Downloading playlist: <title>`,
|
# `[download] Finished downloading playlist: <title>`, `[download] Downloading playlist: <title>`,
|
||||||
# `… Skipping already downloaded playlist: <title>` — the title runs to the end of the line.
|
# `… 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)
|
_TITLE_TAIL_RE = re.compile(r"(playlist: |\[download\] Downloading \w+: ).*", re.I)
|
||||||
# An id quoted mid-sentence, not as a prefix.
|
# An id quoted mid-sentence, not as a prefix: `… not available for <id>`, and `--no-playlist`'s
|
||||||
_BARE_ID_RE = re.compile(r"((?:subtitles not available for|Downloading just video) )[^\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
|
# 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.
|
# leaves behind, and it must survive this one.
|
||||||
_PATH_RE = re.compile(r"(?<![\w.…])/(?:[^/\s\"']+/)+[^/\s\"']*")
|
_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:
|
def log_safe(text: object) -> str:
|
||||||
"""yt-dlp's text (its own lines, or a DownloadError's message) with the parts that name a
|
"""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,
|
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
|
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."""
|
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 = _ID_PREFIX_RE.sub(r"\1…:", text)
|
||||||
text = _GENERIC_ID_RE.sub(r"\1…:", text)
|
text = _GENERIC_ID_RE.sub(r"\1…:", text)
|
||||||
text = _PLAYLIST_TITLE_RE.sub(r"\1…", text)
|
text = _PLAYLIST_TITLE_RE.sub(r"\1…", text)
|
||||||
|
|||||||
@@ -654,30 +654,28 @@ def _download(
|
|||||||
diagnosis = dlerrors.diagnose(msg, url=url, cookie_attached=cookiefile is not None)
|
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).
|
# 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)
|
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
|
with SessionLocal() as db:
|
||||||
# failed, that write fails too, and the failure would otherwise leave no line at all.
|
asset = db.get(MediaAsset, asset_id)
|
||||||
try:
|
if asset:
|
||||||
with SessionLocal() as db:
|
asset.status = "error"
|
||||||
asset = db.get(MediaAsset, asset_id)
|
asset.error = msg
|
||||||
if asset:
|
# Atomic fail: only while still running, so a route-set cancel/pause is never
|
||||||
asset.status = "error"
|
# overwritten with `error` (error also holds the asset → would re-open the
|
||||||
asset.error = msg
|
# double-release class).
|
||||||
# Atomic fail: only while still running, so a route-set cancel/pause is never
|
service.finalize_if_running(
|
||||||
# overwritten with `error` (error also holds the asset → would re-open the
|
db,
|
||||||
# double-release class).
|
job_id,
|
||||||
service.finalize_if_running(
|
status=JobStatus.ERROR,
|
||||||
db,
|
error=msg,
|
||||||
job_id,
|
error_code=diagnosis.code,
|
||||||
status=JobStatus.ERROR,
|
error_detail=diagnosis.detail,
|
||||||
error=msg,
|
phase=None,
|
||||||
error_code=diagnosis.code,
|
)
|
||||||
error_detail=diagnosis.detail,
|
db.commit()
|
||||||
phase=None,
|
# 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.
|
||||||
db.commit()
|
# silent-ok: not silent — `_log_download_failed` is the report.
|
||||||
finally:
|
_log_download_failed(job_id, msg, diagnosis.code, exc)
|
||||||
# silent-ok: not silent — `_log_download_failed` is the report.
|
|
||||||
_log_download_failed(job_id, msg, diagnosis.code, exc)
|
|
||||||
finally:
|
finally:
|
||||||
# Unlink the decrypted cookie file explicitly (the rmtree below removes the whole staging
|
# 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).
|
# 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.
|
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`).
|
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)."""
|
Logged after the write, as on the download error path."""
|
||||||
try:
|
with SessionLocal() as db:
|
||||||
with SessionLocal() as db:
|
asset = db.get(MediaAsset, asset_id)
|
||||||
asset = db.get(MediaAsset, asset_id)
|
if asset:
|
||||||
if asset:
|
asset.status = "error"
|
||||||
asset.status = "error"
|
asset.error = msg
|
||||||
asset.error = msg
|
# Atomic fail: only while still running (see the download error path).
|
||||||
# Atomic fail: only while still running (see the download error path).
|
service.finalize_if_running(
|
||||||
service.finalize_if_running(
|
db,
|
||||||
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",
|
|
||||||
job_id,
|
job_id,
|
||||||
formats.log_safe(msg),
|
status=JobStatus.ERROR,
|
||||||
extra={
|
error=msg,
|
||||||
**logs.event(
|
error_code=dlerrors.classify(msg),
|
||||||
"edit.job.failed",
|
phase=None,
|
||||||
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 {}),
|
|
||||||
},
|
|
||||||
)
|
)
|
||||||
|
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:
|
def _process_edit(job_id: int, asset_id: int) -> None:
|
||||||
|
|||||||
@@ -21,6 +21,7 @@ from app import logsink
|
|||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.db import SessionLocal
|
from app.db import SessionLocal
|
||||||
from app.downloads import edit as editmod
|
from app.downloads import edit as editmod
|
||||||
|
from app.downloads import formats
|
||||||
from app.models import DownloadJob
|
from app.models import DownloadJob
|
||||||
|
|
||||||
log = logs.get_logger(__name__)
|
log = logs.get_logger(__name__)
|
||||||
@@ -81,14 +82,40 @@ def main() -> None:
|
|||||||
if asset_id is None:
|
if asset_id is None:
|
||||||
return
|
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
|
# 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.
|
# 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
|
from app.downloads.pipeline import _download, _process_edit
|
||||||
|
|
||||||
if job_kind == "edit":
|
with formats.hiding(source_ref):
|
||||||
_process_edit(job_id, asset_id)
|
try:
|
||||||
else:
|
if job_kind == "edit":
|
||||||
_download(job_id, asset_id, source_kind, source_ref, spec, user_id)
|
_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__":
|
if __name__ == "__main__":
|
||||||
|
|||||||
+10
-2
@@ -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`).
|
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
|
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
|
failed = False
|
||||||
try:
|
try:
|
||||||
failed = fail()
|
failed = fail()
|
||||||
|
except BaseException as write_error:
|
||||||
|
write_error.__suppress_context__ = True
|
||||||
|
raise
|
||||||
finally:
|
finally:
|
||||||
log.error(
|
log.error(
|
||||||
"job %s: worker error (%s)",
|
"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
|
# 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`.
|
# worker thread for good; boot recovery settles a job left `running`.
|
||||||
except Exception: # noqa: BLE001
|
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:
|
def main() -> None:
|
||||||
|
|||||||
@@ -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")
|
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):
|
def test_a_failure_the_database_would_not_record_is_not_claimed(db, monkeypatch, tmp_path):
|
||||||
"""The database is often what failed; the write of the failure then fails too, and the line
|
"""The job is still `running`: the runner reports this with the write's error, and the worker
|
||||||
that says so must not go down with it."""
|
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")
|
u = _user(db, "fb-dbdown@example.com")
|
||||||
a, j = _asset_and_job(db, u, sig="dbdown", asset_status="downloading", job_status="running")
|
a, j = _asset_and_job(db, u, sig="dbdown", asset_status="downloading", job_status="running")
|
||||||
_fail_the_child(monkeypatch, tmp_path, cookie=False)
|
_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):
|
with pytest.raises(ConnectionError):
|
||||||
pipeline._download(j.id, a.id, "url", _REEL, {}, u.id)
|
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):
|
def test_a_job_meeting_a_failed_shared_asset_gets_the_same_explanation(db):
|
||||||
|
|||||||
@@ -8,6 +8,9 @@ same edit failure twice, a warning per segment request, per settings read).
|
|||||||
|
|
||||||
import json
|
import json
|
||||||
import logging
|
import logging
|
||||||
|
import re
|
||||||
|
import shutil
|
||||||
|
import subprocess
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
from types import SimpleNamespace
|
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
|
assert "exc" not in line
|
||||||
|
|
||||||
|
|
||||||
def test_an_edit_failure_is_reported_even_when_its_write_fails(sink, monkeypatch):
|
def test_an_edit_the_database_would_not_fail_is_not_reported_as_failed(sink, monkeypatch):
|
||||||
"""The database is often what failed; then the write fails too, and the line must not go
|
"""The job is still `running`: the runner reports this failure with the write's, and the
|
||||||
down with it."""
|
worker fails the job (`child_exit`). A line here as well would be a second, and a false one."""
|
||||||
|
|
||||||
class _Down:
|
class _Down:
|
||||||
def __enter__(self):
|
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):
|
with pytest.raises(ConnectionError):
|
||||||
pipeline._fail_edit(9, 3, "boom", KeyError("x"))
|
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):
|
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)
|
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 ------------------------------------------------------------------
|
# --- a repeating failure, once ------------------------------------------------------------------
|
||||||
def test_a_stale_setting_is_reported_once_not_on_every_read(sink, monkeypatch):
|
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")
|
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)
|
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):
|
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
|
"""ffmpeg's CalledProcessError quotes its argv, and the source path in it is built from the
|
||||||
channel and the title."""
|
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_poster(asset, str(tmp_path)) is None
|
||||||
assert editmod.ensure_storyboard(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 len(lines) == 2
|
||||||
assert all("Some_Channel" not in json.dumps(o) for o in lines)
|
assert all(
|
||||||
assert all("CalledProcessError" in o["msg"] for o in lines)
|
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"]
|
||||||
|
|||||||
@@ -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["level"] == "ERROR"
|
||||||
assert payload["event"] == "http.request"
|
assert payload["event"] == "http.request"
|
||||||
assert "RuntimeError" in payload["exc"]
|
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
|
||||||
|
|||||||
@@ -134,9 +134,15 @@ def test_the_source_url_does_not_travel_with_the_explanation(sink):
|
|||||||
"hu subtitles not available for …",
|
"hu subtitles not available for …",
|
||||||
"dQw4w9WgXcQ",
|
"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 the video dQw4w9WgXcQ because of --no-playlist",
|
||||||
"[youtube:tab] Downloading just video … 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",
|
"dQw4w9WgXcQ",
|
||||||
),
|
),
|
||||||
# `Destination` is yt-dlp's word, not an id; the path after it is built from the title.
|
# `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)
|
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():
|
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
|
"""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."""
|
line later (`download.job.failed`). The same scrub, or that line puts the URL back."""
|
||||||
|
|||||||
Reference in New Issue
Block a user