fix(logs): deep-review round 1 — say each failure once, and scrub it everywhere

- yt-dlp's text is scrubbed wherever it is logged, not only in the adapter:
  `formats.log_safe` takes out the URL, the `[extractor] <id>:` prefix and
  file paths, and the job-failed, refused, edit-failed and backfill lines use
  it. Done lines log the asset id, not the title-built path. The PII contract
  now bans `rel`/`rel_path`/`title`.
- A traceback goes with a download/edit failure only when it is our own code
  failing; for yt-dlp's DownloadError, our RuntimeErrors and OSErrors its foot
  is the unscrubbed message.
- yt-dlp's `error` maps to WARNING: it fires on attempts the fallback client
  set recovers from; the job's verdict is `download.job.failed`.
- The sink groups a bare `%s` pass-through by its text (numbers folded), and
  a process's last batch closes the repeat window, so a short-lived download
  child still reports what it dropped.
- Worker-side failures (stall, wall-clock, no asset, cached asset error) log
  `download.job.failed` with a cause; they left no line at all before. The
  crash, supervisor-error and non-zero-exit lines carry the code too.
- An edit failure is one coded line in `_fail_edit`, for every path.
- `logs.get_logger("__main__")` resolves to the `-m` module, so the worker
  and the download child keep their names.
- TRACE lines carrying user content are gated on `logs.consented_trace()`,
  not on the process level; a contract test pins it.
- The OAuth token refresh goes through `_upstream_failure`; transport errors
  carry reason `transport`. Subscribe recognises a duplicate by reason code
  only (the prose fallback was dead).
- Once-only guards for a stale sysconfig override and a refusing HLS session
  directory; item_detail splits Plex failures from our own parse bugs.
- The playlist breaker line names the playlist and the action; comments that
  were false (runner noqa, `_merge_vtt`, sink grouping) are corrected.
This commit is contained in:
2026-09-18 03:16:15 +02:00
parent 04b58e5c6f
commit 54d19cc386
22 changed files with 834 additions and 141 deletions
@@ -0,0 +1,69 @@
"""Subscribing when YouTube says no — and when "no" means "you already are".
The error no longer carries YouTube's body (it is the request quoted back, and it went into a log
line and a 422), so "already following" is recognised by the reason code and nothing else.
DB lane.
"""
import pytest
from fastapi import HTTPException
from sqlalchemy import select
from app.models import Channel, Subscription
from app.routes import channels
from app.youtube.client import YouTubeError
def _youtube_refusing(reason: str):
class _Client:
def __init__(self, db, user):
pass
def __enter__(self):
return self
def __exit__(self, *exc):
return False
def insert_subscription(self, channel_id):
raise YouTubeError(f"POST subscriptions -> 400: {reason}", reason=reason)
def get_channels(self, ids):
return []
return _Client
@pytest.fixture
def stub_channel(db):
db.add(Channel(id="UCdup", title="Already followed"))
db.commit()
return "UCdup"
@pytest.mark.parametrize("reason", ["subscriptionDuplicate", "quotaExceeded,subscriptionDuplicate"])
def test_already_following_on_youtube_is_recorded_not_refused(
db, make_user, monkeypatch, stub_channel, reason
):
user = make_user()
monkeypatch.setattr(channels, "YouTubeClient", _youtube_refusing(reason))
channels.subscribe(stub_channel, user=user, db=db)
sub = db.execute(
select(Subscription).where(
Subscription.user_id == user.id, Subscription.channel_id == stub_channel
)
).scalar_one()
assert sub is not None
@pytest.mark.parametrize("reason", ["quotaExceeded", "<none>", "<unparseable>"])
def test_any_other_refusal_is_answered_with_a_422(db, make_user, monkeypatch, stub_channel, reason):
user = make_user()
monkeypatch.setattr(channels, "YouTubeClient", _youtube_refusing(reason))
with pytest.raises(HTTPException) as caught:
channels.subscribe(stub_channel, user=user, db=db)
assert caught.value.status_code == 422
+220
View File
@@ -0,0 +1,220 @@
"""E22.5 review round 1: a failure is reported once, with its code, and a repeating one is not a
flood.
Each case here is a place where the first sweep got the line wrong in one of two directions: a
failure that left no line at all (a download the watchdog killed), or one that left too many (the
same edit failure twice, a warning per segment request, per settings read).
"""
import json
import logging
from pathlib import Path
from types import SimpleNamespace
import pytest
import yt_dlp
from app import logs, sysconfig, worker
from app.downloads import pipeline
from app.plex import stream as plex_stream
class _Sink(logging.Handler):
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]
def events(self, code: str) -> list[dict]:
return [o for o in self.objects() if o.get("event") == code]
@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)
class _NoDb:
"""A session that finds nothing and commits nothing — these cases are about the line."""
def __enter__(self):
return self
def __exit__(self, *exc):
return False
def get(self, *a, **k):
return None
def commit(self):
pass
@pytest.fixture
def finalized(monkeypatch):
"""Whether `finalize_if_running` fires: True unless a case says a route got there first."""
state = {"fires": True}
monkeypatch.setattr(worker, "SessionLocal", _NoDb)
monkeypatch.setattr(pipeline, "SessionLocal", _NoDb)
fire = lambda db, job_id, **fields: state["fires"] # noqa: E731
monkeypatch.setattr(worker.service, "finalize_if_running", fire)
return state
# --- the worker's own failures ---------------------------------------------------------------
@pytest.mark.parametrize("cause", ["stalled", "timeout"])
def test_a_download_the_watchdog_kills_leaves_a_coded_line(sink, finalized, cause):
"""The child is killed, so it never reports; before this the worker did not either, and a
stalled download failed with no line anywhere."""
worker._fail_running(42, error="stopped", error_code="network", cause=cause)
(line,) = sink.events("download.job.failed")
assert line["level"] == "WARNING"
assert line["attrs"] == {"job_id": 42, "error_code": "network", "cause": cause}
def test_a_job_a_route_already_stopped_is_not_reported_as_failed(sink, finalized):
finalized["fires"] = False
worker._fail_running(42, error="stopped", error_code="network", cause="stalled")
assert sink.events("download.job.failed") == []
def test_a_caller_with_its_own_line_is_not_reported_twice(sink, finalized):
worker._fail_running(42, error="Worker error", error_code=None)
assert sink.events("download.job.failed") == []
# --- an edit failure, once ---------------------------------------------------------------------
def test_an_edit_failure_is_one_line_with_its_code_and_our_own_stack(sink, finalized):
try:
raise TypeError("a spec shape nobody expected")
except TypeError as exc:
pipeline._fail_edit(9, 3, str(exc), exc)
(line,) = sink.events("edit.job.failed")
assert line["attrs"] == {"job_id": 9, "asset_id": 3, "error_type": "TypeError"}
assert "TypeError" in line["exc"]
assert len([o for o in sink.objects() if o["level"] in ("WARNING", "ERROR")]) == 1
def test_an_edit_that_ffmpeg_refused_names_no_file_and_carries_no_stack(sink, finalized):
"""ffmpeg's stderr tail names its input, whose path is the channel and the title. The message
is scrubbed; the stack is left off, because its last line is the same text unscrubbed."""
msg = "ffmpeg failed (1): /downloads/Some_Channel/Season_2024/A_Private_Title_a3.mp4: Invalid data"
pipeline._fail_edit(9, 3, msg, RuntimeError(msg))
(line,) = sink.events("edit.job.failed")
assert "A_Private_Title" not in json.dumps(line)
assert "exc" not in line
def test_an_edit_whose_source_is_gone_is_found_by_the_same_code(sink, finalized):
pipeline._fail_edit(9, 3, "The source file is missing.")
(line,) = sink.events("edit.job.failed")
assert line["attrs"] == {"job_id": 9, "asset_id": 3}
# --- a download failure, scrubbed ---------------------------------------------------------------
def test_a_failed_download_line_does_not_put_back_what_the_adapter_took_out(sink):
"""yt-dlp logs its error through the adapter (scrubbed) and then raises the same text, which
the pipeline logs again. Unscrubbed, that second line is the URL the first one hid."""
msg = "ERROR: Unsupported URL: https://example.org/private/path?id=123"
pipeline._log_download_failed(5, msg, "unknown", yt_dlp.utils.DownloadError(msg))
(line,) = sink.events("download.job.failed")
assert "private/path" not in json.dumps(line)
assert "example.org/…" in line["msg"]
# Unclassified, but yt-dlp's own error: its stack is the `except`, its foot the raw text.
assert "exc" not in line
def test_an_unclassified_failure_of_our_own_keeps_its_stack(sink):
try:
raise KeyError("requested_formats")
except KeyError as exc:
pipeline._log_download_failed(5, str(exc), "unknown", exc)
(line,) = sink.events("download.job.failed")
assert "KeyError" in line["exc"]
assert line["attrs"]["error_type"] == "KeyError"
def test_the_metadata_backfill_names_the_asset_and_not_the_download(sink, monkeypatch):
from app.downloads import adapters, backfill
url = "https://www.youtube.com/watch?v=dQw4w9WgXcQ"
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(
f"ERROR: [youtube] dQw4w9WgXcQ: Video unavailable ({target})"
)
monkeypatch.setattr(backfill.yt_dlp, "YoutubeDL", _Refusing)
assert backfill._extract_meta(url, adapters.YouTubeAdapter(), 11) is None
lines = [o for o in sink.objects() if "meta extract failed" in o["msg"]]
assert lines and all("dQw4w9WgXcQ" 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")
monkeypatch.setattr(sysconfig, "_raw_override", lambda db, key: "not-a-number")
monkeypatch.setattr(sysconfig, "_coerce_warned", set())
for _ in range(3):
sysconfig.get(None, spec.key)
assert len(sink.events("sysconfig.override_uncoercible")) == 1
class _RefusingDir:
"""A session directory on a disk that has gone away: every probe raises."""
def __truediv__(self, name):
return SimpleNamespace(exists=self._refuse)
@staticmethod
def _refuse():
raise PermissionError("the disk went read-only")
def test_a_refusing_session_directory_is_reported_once_per_session(sink):
"""Every segment request probes, and hls.js retries each 404 — a line per probe is a flood."""
session = plex_stream.HlsSession("k", Path("."), None, 0.0, ())
session.dir = _RefusingDir()
for seq in (3, 4, 5):
assert not plex_stream.artifact_may_arrive(session, plex_stream.segment_name(seq, None))
(line,) = sink.events("plex.stream.segment_probe_failed")
assert line["attrs"]["reason"] == "PermissionError"
+92 -4
View File
@@ -87,15 +87,62 @@ def test_an_upstream_failure_logs_the_reason_code_and_not_the_body(sink):
assert err.reason == "quotaExceeded"
def test_the_body_is_kept_for_the_one_user_who_consented_to_it(sink):
@pytest.fixture
def consented():
"""The request scope of a user who turned Teljes (TRACE) on for themselves."""
scope = logs._RequestScope()
scope.user_id, scope.level = 7, logs.TRACE
token = logs._scope.set(scope)
try:
yield
finally:
logs._scope.reset(token)
def test_the_body_is_kept_for_the_one_user_who_consented_to_it(sink, consented):
_upstream_failure("GET", "search", _youtube_403(TERM))
# TRACE is emitted only while the user has turned Teljes on for their own session, which is
# exactly the consent the privacy policy describes. The diagnostic is not lost, it is gated.
# The diagnostic is not lost, it is gated — on the consent the privacy policy describes.
(trace,) = sink.at("TRACE")
assert TERM in trace["attrs"]["body"]
def test_a_process_running_at_trace_is_not_anyones_consent(sink):
"""`sink` runs the whole tree at TRACE — what an admin setting `log_level` to TRACE does. That
buys more detail, not every user's search terms quoted back (`logs._traced`)."""
_upstream_failure("GET", "search", _youtube_403(TERM))
assert sink.at("TRACE") == []
assert TERM not in json.dumps(sink.objects())
def test_a_scope_with_no_elevation_is_not_consent():
scope = logs._RequestScope()
scope.user_id = 7
token = logs._scope.set(scope)
try:
assert not logs.consented_trace()
finally:
logs._scope.reset(token)
assert not logs.consented_trace() # a scheduler thread: no request at all
def test_a_refused_token_refresh_names_the_oauth_reason_and_not_its_prose(sink):
"""The token endpoint's error is `{"error": "<code>", "error_description": <prose>}` — not the
Data API's shape. It goes through the same door, so it gets the same treatment."""
resp = httpx.Response(
400,
json={"error": "invalid_grant", "error_description": "Token has been expired or revoked."},
request=httpx.Request("POST", "https://oauth2.googleapis.com/token"),
)
err = _upstream_failure("POST", "oauth2/token", resp)
(line,) = sink.at("WARNING")
assert line["attrs"]["reason"] == "invalid_grant"
assert err.reason == "invalid_grant"
assert "revoked" not in str(err) and "revoked" not in json.dumps(line)
def test_an_unparseable_body_still_names_the_status(sink):
"""A proxy answering HTML has no `reason` to take — the line must still be worth reading, and
must still not fall back to printing the body."""
@@ -153,9 +200,16 @@ _BANNED_NAMES = frozenset(
"source_url",
"source_webpage_url",
"password",
# A download's path is built from its channel and its title (`storage.rel_path`), so it
# names what someone downloaded exactly as the URL does. Log the asset id.
"rel",
"rel_path",
"title",
}
)
_BANNED_ATTRS = frozenset({"text", "content", "email", "url", "query"})
_BANNED_ATTRS = frozenset(
{"text", "content", "email", "url", "query", "rel_path", "title", "display_name"}
)
_ESCAPE = "log-pii-ok"
_LOG_METHODS = frozenset(
{"debug", "info", "warning", "warn", "error", "exception", "critical", "log"}
@@ -211,3 +265,37 @@ def test_no_log_call_passes_what_a_person_typed():
f"the argument (or the line directly above the call) `# {_ESCAPE}: <why it is "
f"safe>` — {offenders}"
)
def _guarded_by_consent(node: ast.AST, parents: dict[ast.AST, ast.AST]) -> bool:
while node in parents:
node = parents[node]
if isinstance(node, ast.If):
for sub in ast.walk(node.test):
if isinstance(sub, ast.Attribute) and sub.attr == "consented_trace":
return True
return False
def test_every_escaped_trace_line_is_gated_on_the_users_own_consent():
"""`log-pii-ok` on a TRACE line means "this is what the user's Teljes consent is for". The TRACE
level alone does not hold that promise: an admin can run the whole process at TRACE, and a
scheduler thread has no user at all. So the line must sit under `logs.consented_trace()`."""
root = pathlib.Path(__file__).resolve().parents[1] / "app"
offenders = []
for path in sorted(root.rglob("*.py")):
src = path.read_text(encoding="utf-8")
lines = src.splitlines()
tree = ast.parse(src)
parents = {child: node for node in ast.walk(tree) for child in ast.iter_child_nodes(node)}
for node in ast.walk(tree):
if not _is_log_call(node) or not _offending(node):
continue
first = node.args[0] if node.args else None
at_trace = isinstance(first, ast.Attribute) and first.attr == "TRACE"
span = " ".join(lines[max(0, node.lineno - 2) : (node.end_lineno or node.lineno)])
if at_trace and _ESCAPE in span and not _guarded_by_consent(node, parents):
offenders.append(f"{path.relative_to(root)}:{node.lineno}")
assert offenders == [], (
f"a TRACE line with user content is not under consented_trace(): {offenders}"
)
+49 -7
View File
@@ -13,6 +13,8 @@ the rule, because the rule is only worth having if a hand-rolled name fails the
import ast
import logging
import pathlib
import sys
import types
import pytest
@@ -29,8 +31,8 @@ _ESCAPE = "logger-name-ok"
("app.plex.stream", "siftlode.plex.stream"),
("app.routes.channels", "siftlode.routes.channels"),
("app.worker", "siftlode.worker"),
# Not a module of ours (a script, a doctest): it lands on the root of our tree rather than
# inventing `siftlode.__main__`, which nothing would think to filter on.
# A script that is not a module of ours (pytest itself, here): it lands on the root of our
# tree rather than inventing `siftlode.__main__`, which nothing would think to filter on.
("__main__", "siftlode"),
],
)
@@ -38,6 +40,32 @@ def test_the_name_follows_the_module(module, expected):
assert logs.get_logger(module).name == expected
@pytest.mark.parametrize(
("spec_name", "expected"),
[
# How the worker and the download child actually run: `python -m app.worker`, and the
# worker's own `[sys.executable, "-m", "app.downloads.runner", ...]`. `__name__` is
# `__main__` in both, and taken at its word both processes logged as the bare root.
("app.worker", "siftlode.worker"),
("app.downloads.runner", "siftlode.downloads.runner"),
],
)
def test_a_module_run_with_dash_m_keeps_its_own_name(monkeypatch, spec_name, expected):
main = types.ModuleType("__main__")
main.__spec__ = types.SimpleNamespace(name=spec_name)
monkeypatch.setitem(sys.modules, "__main__", main)
assert logs.get_logger("__main__").name == expected
def test_a_plain_script_has_no_spec_and_stays_the_root(monkeypatch):
main = types.ModuleType("__main__")
main.__spec__ = None
monkeypatch.setitem(sys.modules, "__main__", main)
assert logs.get_logger("__main__").name == "siftlode"
def test_every_derived_logger_stays_under_the_one_tree():
"""`configure_logging` hangs the level and the handler off the root, and the tests attach their
sink to `siftlode` — a name outside that tree would be invisible to both."""
@@ -62,11 +90,25 @@ def test_no_module_hand_rolls_a_logger_name():
if not isinstance(node, ast.Call):
continue
func = node.func
if not (isinstance(func, ast.Attribute) and func.attr == "getLogger"):
continue
# A no-argument `logging.getLogger()` is the ROOT logger — level plumbing, not a
# module's own logger, and nothing to name.
if not node.args:
called = (
func.attr
if isinstance(func, ast.Attribute)
else func.id
if isinstance(func, ast.Name)
else ""
)
if called == "get_logger":
# The derivation itself is only as good as its argument: a literal here does not
# name a module, it collapses to the root and pools modules together again.
arg = node.args[0] if len(node.args) == 1 else None
if isinstance(arg, ast.Name) and arg.id == "__name__" and not node.keywords:
continue
elif called == "getLogger":
# A no-argument `logging.getLogger()` is the ROOT logger — level plumbing, not a
# module's own logger, and nothing to name. A `name=` keyword is still a name.
if not node.args and not node.keywords:
continue
else:
continue
start = max(0, node.lineno - 2) # the call's lines, plus the one above it
span = " ".join(lines[start : (node.end_lineno or node.lineno)])
+34
View File
@@ -90,6 +90,40 @@ def test_a_flood_of_one_message_is_stored_up_to_the_limit_and_then_summarised(st
assert notice.attrs["template"] == "RSS poll skipped for channel %s: HTTP 404"
def test_a_pass_through_template_groups_by_its_text_not_by_the_bare_placeholder(stored):
"""`"%s"` is how the yt-dlp adapter hands over yt-dlp's own line, and as a key it says nothing:
every distinct warning would share one bucket and the thirty-first — whatever it said — would be
dropped as a "repeat" of the first. The text groups instead, numbers folded, so a retry storm is
still one repeat and the warning that explains the failure still gets through."""
sink, log, rows = stored
limit = logsink.REPEATS_PER_MINUTE
for i in range(limit + 10):
log.warning("%s", f"[download] Got error: timed out. Retrying fragment {i} (1/10)...")
log.warning("%s", "[youtube] …: Requested format is not available")
stored_rows = rows()
assert len(stored_rows) == limit + 1
assert stored_rows[-1].msg == "[youtube] …: Requested format is not available"
sink._repeats.started -= logsink.REPEAT_WINDOW_SECONDS
notice = rows()[-1]
assert notice.attrs["suppressed"] == 10
assert notice.attrs["template"].startswith(
"[download] Got error: timed out. Retrying fragment #"
)
def test_a_process_that_ends_inside_the_minute_still_says_what_it_dropped(stored):
"""Every download child lives well under the limiter's minute. Its last batch closes the window
early, or the repeats it dropped would go unreported."""
sink, log, rows = stored
for i in range(logsink.REPEATS_PER_MINUTE + 3):
log.warning("RSS poll skipped for channel %s: HTTP 404", f"UC{i}")
rows()
sink.write_pending(final=True)
notice = rows()[-1]
assert notice.event == "log.repeats_suppressed"
assert notice.attrs["suppressed"] == 3
def test_request_lines_are_never_treated_as_a_flood(stored):
_sink, log, rows = stored
for _ in range(logsink.REPEATS_PER_MINUTE + 5):
+43 -1
View File
@@ -59,7 +59,10 @@ def sink():
("debug", "TRACE"),
("info", "DEBUG"),
("warning", "WARNING"),
("error", "ERROR"),
# yt-dlp calls `error` from `trouble()` just before it raises, on every failed ATTEMPT —
# the pipeline's fallback client set then often succeeds. The job's verdict is the
# pipeline's `download.job.failed`, not this.
("error", "WARNING"),
],
)
def test_each_ytdlp_level_lands_where_it_belongs(sink, method, level):
@@ -83,6 +86,45 @@ def test_the_source_url_does_not_travel_with_the_explanation(sink):
assert "Requested format is not available" in line["msg"]
@pytest.mark.parametrize(
("line", "kept", "gone"),
[
# The shape nearly every yt-dlp warning and error has: no URL, the id as a prefix.
(
"ERROR: [youtube] dQw4w9WgXcQ: Video unavailable",
"ERROR: [youtube] …: Video unavailable",
"dQw4w9WgXcQ",
),
# The generic extractor's "id" is the URL's own basename.
(
"WARNING: [generic] my-private-holiday-clip: Falling back on generic information",
"WARNING: [generic] …: Falling back on generic information",
"my-private-holiday-clip",
),
# `Destination` is yt-dlp's word, not an id; the path after it is built from the title.
(
"[download] Destination: /downloads/Some_Channel/Season_2024/A_Private_Title_a7.mp4",
"[download] Destination: …",
"A_Private_Title",
),
],
)
def test_what_names_the_download_comes_out_of_real_ytdlp_shapes(sink, line, kept, gone):
formats._YDL_LOG.warning(line)
(obj,) = sink.objects()
assert obj["msg"] == kept
assert gone not in json.dumps(obj)
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."""
text = "ERROR: Unsupported URL: https://example.org/private/path?id=123"
assert formats.log_safe(text) == "ERROR: Unsupported URL: example.org/…"
def test_a_line_with_no_url_is_left_alone(sink):
formats._YDL_LOG.warning("nsig extraction failed: Some formats may be missing")