peter
ed4ab4e13c
Bug hunt 2026-09, items 8 and 12 — the two things the Plex player was measurably
lying about.
Item 8: picking a subtitle track showed nothing for a long time, and the reported
workaround was to stop/start until it suddenly worked. Measured on prod against a
17.06 GB MKV with two embedded SubRip tracks:
full pass, one track 154 s
full pass, both tracks in ONE run 111 s
-c:s copy (no WebVTT conversion) 143 s
from 1:00:00 to the end of file 66 s
a 630 s window at 1:00:00, both 8 s
So the conversion was never the cost: ffmpeg streams every byte of the container
between its seek point and its stop point, and the array delivers ~140 MB/s. The
only lever is reading less. Three changes follow from that:
* a window around the playhead is extracted and published FIRST (seconds), and
the full pass completes behind it;
* every embedded text track rides that same single read — picking Hungarian used
to cost a full pass and then switching to English cost another one;
* none of it happens inside a request any more. The endpoint answers 202 while a
background worker extracts, the player polls /status (carrying its position, so
the window follows the viewer), and one ffmpeg run finally has a timeout.
-copyts is deliberately absent from a windowed pass: with it ffmpeg ignores -t and
reads the whole container anyway (measured — a [0, 600 s] window still took the
full 145 s), so a window comes back on a zero-based clock and is shifted to
absolute time here. Cached tracks written by older builds have no coverage sidecar
and count as complete, so nothing is re-extracted after the upgrade.
The <track> is no longer mounted before the server has something to put in it; a
"Preparing subtitles: …" notice stands in, and a track that can never be shown says
why instead of leaving the viewer to conclude the picker does nothing.
Item 12: "Bitrate" read a constant 211 kbps on every remux, because it was the
master playlist's BANDWIDTH — which ffmpeg derives from the one stream whose rate
it knows, the -b:a 192k AAC track, plus 10%. It is a measurement now: bytes per
second of MEDIA from hls.js FRAG_LOADED, accumulated per fragment type and summed
(a multi-audio session's video and audio renditions cover the same media seconds,
so pooling them would report half the truth), and an honest dash until the first
fragment lands. The panel also finally names the audio and subtitle track in play.
Verified in the browser against the real Plex library, and every new test
mutation-checked.
264 lines
11 KiB
Python
264 lines
11 KiB
Python
"""Subtitle extraction must not happen inside the request, and must read as little as possible.
|
|
|
|
Bug hunt 2026-09, item 8 — "switching the subtitle track shows nothing; after a few stop/starts it
|
|
suddenly works". Measured on prod against a 17.06 GB MKV with two embedded SubRip tracks:
|
|
|
|
full pass, one track 154 s | both tracks in ONE run 111 s | a 630 s window at 1:00:00 8 s
|
|
|
|
The cost is not the WebVTT conversion, it is that ffmpeg streams every byte of the container between
|
|
its seek point and its stop point. The old endpoint did that pass INSIDE the <track>'s request, once
|
|
per track, with no timeout — so the browser sat on an empty track for minutes (and an API worker
|
|
thread sat with it), and picking the second language cost the whole read again.
|
|
|
|
These tests pin the three things that fixes it: the request never waits for ffmpeg, the extraction
|
|
publishes a window around the playhead before the whole track, and one ffmpeg run covers every
|
|
embedded text track. Pure — no Postgres, no ffmpeg.
|
|
"""
|
|
|
|
import subprocess
|
|
import threading
|
|
import time
|
|
from pathlib import Path
|
|
|
|
import pytest
|
|
from fastapi.testclient import TestClient
|
|
|
|
import app.state as app_state
|
|
from app.main import app
|
|
from app.plex import subtitles
|
|
from app.routes.plex import playback
|
|
|
|
|
|
@pytest.fixture(autouse=True)
|
|
def _isolated_cache(tmp_path, monkeypatch):
|
|
"""A throwaway cache root + empty registries: this module's state is process-global."""
|
|
monkeypatch.setattr(subtitles, "CACHE_DIR", tmp_path)
|
|
subtitles.reset_state()
|
|
yield
|
|
subtitles.reset_state()
|
|
|
|
|
|
@pytest.fixture
|
|
def client(monkeypatch) -> TestClient:
|
|
# The subtitle endpoints authenticate off the signed session cookie directly (not a FastAPI
|
|
# dependency), so there is no dependency_overrides hook to use.
|
|
monkeypatch.setattr(playback, "resolved_user_id", lambda request: (1, None))
|
|
monkeypatch.setattr(app_state, "_configured_cache", True) # pass the instance-setup gate, no DB
|
|
return TestClient(app)
|
|
|
|
|
|
class _ManualPool:
|
|
"""Deterministic stand-in for the extraction thread pool: jobs run when the test says so."""
|
|
|
|
def __init__(self) -> None:
|
|
self.jobs: list[tuple] = []
|
|
|
|
def submit(self, fn, *args) -> None:
|
|
self.jobs.append((fn, args))
|
|
|
|
def run_next(self) -> None:
|
|
fn, args = self.jobs.pop(0)
|
|
fn(*args)
|
|
|
|
def run_all(self) -> int:
|
|
jobs, self.jobs = self.jobs, []
|
|
for fn, args in jobs:
|
|
fn(*args)
|
|
return len(jobs)
|
|
|
|
|
|
def _cue(start: str, end: str, text: str) -> str:
|
|
return f"{start} --> {end}\n{text}"
|
|
|
|
|
|
def _vtt(*cues: str) -> str:
|
|
return "WEBVTT\n\n" + "\n\n".join(cues) + "\n"
|
|
|
|
|
|
# --- the request must never wait for the extraction ---------------------------------------------
|
|
|
|
|
|
def test_a_cold_track_answers_at_once_instead_of_waiting_for_ffmpeg(client, monkeypatch):
|
|
"""THE regression. A cold track used to block the request for the length of a full file read;
|
|
now it answers 202 and the extraction runs behind it. Timed, because "does it block?" is the
|
|
whole question — the fake extraction holds a worker for 5 s, which the request must not feel."""
|
|
started = threading.Event()
|
|
release = threading.Event()
|
|
|
|
def _slow(rating_key, sub_ord, window_start):
|
|
started.set()
|
|
release.wait(timeout=5)
|
|
|
|
monkeypatch.setattr(subtitles, "_extract_and_publish", _slow)
|
|
try:
|
|
t0 = time.monotonic()
|
|
resp = client.get("/api/plex/subtitle/98614/0")
|
|
elapsed = time.monotonic() - t0
|
|
assert resp.status_code == 202, resp.text
|
|
assert elapsed < 2.0, f"the request waited {elapsed:.1f}s on the extraction"
|
|
assert started.wait(timeout=5), "the extraction never started in the background"
|
|
# …and the status endpoint answers just as fast while that extraction is still running.
|
|
t0 = time.monotonic()
|
|
st = client.get("/api/plex/subtitle/98614/0/status")
|
|
assert st.status_code == 200 and st.json()["state"] == "preparing"
|
|
assert time.monotonic() - t0 < 2.0
|
|
finally:
|
|
release.set()
|
|
|
|
|
|
def test_a_burst_of_polls_starts_one_window_and_one_full_pass(monkeypatch):
|
|
"""The player polls once a second while it waits. Each poll must JOIN the running jobs, not
|
|
start another ffmpeg over the same 17 GB."""
|
|
pool = _ManualPool()
|
|
monkeypatch.setattr(subtitles, "_POOL", pool)
|
|
for _ in range(5):
|
|
subtitles.ensure("98614", 0, at=600.0)
|
|
assert len(pool.jobs) == 2 # one window (at 600 s) + the one full pass
|
|
# submit(_run, ident, rating_key, sub_ord, window_start) — the last arg is what distinguishes them
|
|
assert [a[3] for _, a in pool.jobs] == [570.0, None] # the window first, then the full pass
|
|
|
|
|
|
# --- window first, whole track after ------------------------------------------------------------
|
|
|
|
|
|
def test_status_walks_preparing_to_partial_to_ready(client, monkeypatch):
|
|
"""A window around the playhead makes the track showable long before it is complete, and the
|
|
generation changes when it grows so the browser refetches instead of keeping the short VTT."""
|
|
pool = _ManualPool()
|
|
monkeypatch.setattr(subtitles, "_POOL", pool)
|
|
key = subtitles.cache_key("98614", 0)
|
|
|
|
def _publish(rating_key, sub_ord, window_start):
|
|
if window_start is not None:
|
|
subtitles.publish(
|
|
key, _vtt(_cue("59:54.187", "59:58.650", "window")), (3570.0, 3900.0), False
|
|
)
|
|
else:
|
|
subtitles.publish(key, _vtt(_cue("01:12.000", "01:15.000", "whole")), (0.0, 1e9), True)
|
|
|
|
monkeypatch.setattr(subtitles, "_extract_and_publish", _publish)
|
|
|
|
first = client.get("/api/plex/subtitle/98614/0/status?at=3600").json()
|
|
assert first["state"] == "preparing" and first["gen"] == 0
|
|
|
|
pool.run_next() # the window job, submitted first — the full pass stays queued behind it
|
|
windowed = client.get("/api/plex/subtitle/98614/0/status?at=3600").json()
|
|
assert windowed["state"] == "partial", "a window around the playhead is showable"
|
|
assert windowed["gen"] > 0
|
|
# …and the <track> request now gets real WebVTT rather than another 202.
|
|
served = client.get("/api/plex/subtitle/98614/0?at=3600")
|
|
assert served.status_code == 200 and "window" in served.text
|
|
|
|
pool.run_next() # the full pass, scheduled by that same first poll
|
|
done = client.get("/api/plex/subtitle/98614/0/status?at=3600").json()
|
|
assert done["state"] == "ready"
|
|
assert done["gen"] != windowed["gen"], "a widened track must not reuse the window's generation"
|
|
assert "whole" in client.get("/api/plex/subtitle/98614/0").text
|
|
|
|
|
|
def test_a_position_outside_the_extracted_window_is_not_called_showable(client, monkeypatch):
|
|
"""Honest states: cues exist, but none for where the viewer just seeked to. Saying "ready" there
|
|
would put an empty track on screen with no explanation — the original complaint."""
|
|
pool = _ManualPool()
|
|
monkeypatch.setattr(subtitles, "_POOL", pool)
|
|
subtitles.publish(
|
|
subtitles.cache_key("98614", 0),
|
|
_vtt(_cue("00:10.000", "00:12.000", "x")),
|
|
(0.0, 330.0),
|
|
False,
|
|
)
|
|
assert client.get("/api/plex/subtitle/98614/0/status?at=100").json()["state"] == "partial"
|
|
assert client.get("/api/plex/subtitle/98614/0/status?at=5000").json()["state"] == "preparing"
|
|
|
|
|
|
def test_an_unshowable_track_says_why_and_maps_to_a_status(client, monkeypatch):
|
|
pool = _ManualPool()
|
|
monkeypatch.setattr(subtitles, "_POOL", pool)
|
|
|
|
def _bitmap(rating_key, sub_ord, window_start):
|
|
raise subtitles.SubtitleUnavailable("bitmap")
|
|
|
|
monkeypatch.setattr(subtitles, "_extract_and_publish", _bitmap)
|
|
client.get("/api/plex/subtitle/98614/0/status")
|
|
pool.run_all()
|
|
st = client.get("/api/plex/subtitle/98614/0/status").json()
|
|
assert st["state"] == "failed" and st["code"] == "bitmap"
|
|
resp = client.get("/api/plex/subtitle/98614/0")
|
|
assert resp.status_code == 415 # a structured detail, so the UI can translate it
|
|
assert resp.json()["detail"] == {"code": "subtitle", "reason": "bitmap"}
|
|
|
|
|
|
# --- the ffmpeg pass itself ---------------------------------------------------------------------
|
|
|
|
|
|
def _capture_ffmpeg(monkeypatch) -> list[list[str]]:
|
|
"""Record the argv of each ffmpeg run and satisfy it by writing the outputs it asked for."""
|
|
runs: list[list[str]] = []
|
|
|
|
def _fake_run(cmd, **kwargs):
|
|
runs.append(cmd)
|
|
for i, arg in enumerate(cmd):
|
|
if arg == "-y":
|
|
Path(cmd[i + 1]).write_text(_vtt(_cue("00:01.000", "00:02.000", "hi")), "utf-8")
|
|
return subprocess.CompletedProcess(cmd, 0, b"", b"")
|
|
|
|
monkeypatch.setattr(subtitles.subprocess, "run", _fake_run)
|
|
return runs
|
|
|
|
|
|
def test_one_ffmpeg_run_extracts_every_embedded_text_track(monkeypatch):
|
|
"""The read is the cost and it is SHARED. Extracting one track at a time is what made picking
|
|
Hungarian cost a full pass and then switching to English cost another one."""
|
|
runs = _capture_ffmpeg(monkeypatch)
|
|
out = subtitles._ffmpeg_extract("/plex-media/f.mkv", [0, 1], None, None)
|
|
assert len(runs) == 1, "each extra ffmpeg run is another full read of the file"
|
|
assert set(out) == {0, 1}
|
|
assert runs[0].count("-map") == 2
|
|
|
|
|
|
def test_a_windowed_pass_bounds_the_read_and_never_uses_copyts(monkeypatch):
|
|
"""`-copyts` is the trap: with it ffmpeg IGNORES -t and reads the whole container anyway
|
|
(measured — a [0, 600 s] window still took the full 145 s). So the window is extracted on a
|
|
zero-based clock and shifted back to absolute time by the caller."""
|
|
runs = _capture_ffmpeg(monkeypatch)
|
|
subtitles._ffmpeg_extract("/plex-media/f.mkv", [0], 3570.0, 330.0)
|
|
cmd = runs[0]
|
|
assert "-copyts" not in cmd
|
|
assert cmd[cmd.index("-ss") + 1].startswith(
|
|
"3570"
|
|
) # input seek — before -i, so it is a real seek
|
|
assert cmd.index("-ss") < cmd.index("-i")
|
|
assert cmd[cmd.index("-t") + 1].startswith("330")
|
|
|
|
|
|
def test_the_full_pass_is_not_bounded(monkeypatch):
|
|
runs = _capture_ffmpeg(monkeypatch)
|
|
subtitles._ffmpeg_extract("/plex-media/f.mkv", [0], None, None)
|
|
assert "-t" not in runs[0] and "-ss" not in runs[0]
|
|
|
|
|
|
# --- the pure pieces the above rests on ---------------------------------------------------------
|
|
|
|
|
|
def test_merge_vtt_unions_windows_in_time_order():
|
|
late = _vtt(_cue("59:54.187", "59:58.650", "late"))
|
|
early = _vtt(_cue("01:12.000", "01:15.000", "early"), _cue("59:54.187", "59:58.650", "late"))
|
|
merged = subtitles.merge_vtt(late, early)
|
|
assert merged.startswith("WEBVTT\n\n")
|
|
assert merged.count("-->") == 2, "the shared region must not be duplicated"
|
|
assert merged.index("early") < merged.index("late")
|
|
|
|
|
|
def test_covered_ranges_coalesce_and_answer_membership():
|
|
ranges = subtitles.merge_ranges([[300.0, 600.0], [0.0, 330.0], [900.0, 1200.0]])
|
|
assert ranges == [[0.0, 600.0], [900.0, 1200.0]]
|
|
assert subtitles.covers(ranges, 450.0)
|
|
assert not subtitles.covers(ranges, 700.0)
|
|
|
|
|
|
def test_a_cached_vtt_from_an_older_build_counts_as_complete(tmp_path):
|
|
"""Before this change the cache only ever held whole tracks, and none of them has a sidecar.
|
|
Reading one as "covers nothing" would re-extract every already-cached track after the upgrade."""
|
|
(tmp_path / "sub_98614_0.vtt").write_text(_vtt(_cue("00:01.000", "00:02.000", "x")), "utf-8")
|
|
assert subtitles.read_meta("sub_98614_0") == ([[0.0, 1_000_000_000.0]], True)
|