feat(logs): give the log the events that no request line already carries

The gap this sprint was scoped against turned out to be smaller than the survey
said, and in a way worth writing down: `log_requests` already records every HTTP
call with its route template, status, duration, request id and user id, and the
audit log already records every admin act on someone else's account. Putting a
line in each of routes/downloads.py's twenty mutating endpoints would have added
a second copy of the first and nothing else. So this instruments what neither of
them can see.

yt-dlp now explains itself to our log. `quiet: True` was doing more than quieting:
with no `logger` its whole account of a download went to the child's stdout, 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 — the
real reason a download failed was routinely one line the app never kept. Measured
against the pinned yt-dlp 2026.07.04 before wiring it: with `logger` set it calls
`debug` for extraction and progress lines and `warning`/`error` for the rest, and
neither `quiet` nor `no_warnings` gates those calls. `debug` lands at TRACE, being
several lines a second, so the noisy half is the half the user's own consent
gates. The full source URL is trimmed to its host on the way in — it is a row of
someone's download history, and `logs.set_job` already puts the job id on every
one of these lines. The option is set AFTER the adapter merge, like `cookiefile`
and the size cap: a source adapter must not be able to take away the one account
of what went wrong that a failed job leaves behind.

An HLS session now says which pipeline it got (transcode/remux, hw, tonemap,
variants, offset) — everything downstream is about that choice, and it was only
inferable from an ffmpeg command line nobody keeps. A session culled by the
concurrent-transcode cap says so: somebody's playback stops there, the route turns
it into a retryable 404, and "my film keeps rebuffering" had no other explanation
anywhere. The HW→SW fallback keeps its line and gains an event code.

A live search refused by a quota cap says WHICH cap: the 429 is in the request
line either way, but the per-user daily cap is answered by tomorrow and the shared
budget by the admin.

The download and edit job lifecycle lines gain event codes, which is what E22.6's
console filters on — the job id was already a structured field.

tests/test_ytdlp_logging.py; three of its four cases mutation-checked. A fourth
(a `%` in a progress line) survived its mutation — stdlib only applies `%`
formatting to a record that has args — so it is gone rather than kept as a case
nothing can break; the reasoning moved into the comment on `_emit`.
This commit is contained in:
2026-09-18 01:28:52 +02:00
parent 6b0401b922
commit 04b58e5c6f
5 changed files with 222 additions and 6 deletions
+24 -1
View File
@@ -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: