fix(plex): subtitle windows land where the full pass does, and the extractor stops re-reading, respawning and outliving the process
Deep-review round 2 of the 2026-09 bug hunt, over the round-1 fix diff. - A window was LATE by the distance to the keyframe its input seek landed on, and then doubled for good once the full pass merged in: a cue already running at the window's start came out at a negative time, and the webvtt muxer's default shifted the whole output so it sat at 0. Measured on the real Westworld S01E06 at 25:00: every window cue +5.005 s, 682 cues merged instead of 608. `-avoid_negative_ts disabled` keeps the times exact (the parser reads ffmpeg's signed-field spelling of a negative time); now 608/608 on that file, and a real-ffmpeg test pins it. - A full pass that failed was re-armed every minute while the viewer watched what it did publish — a whole-container read per minute. It now backs off for an hour; windows keep running meanwhile. - A failed WINDOW set the track's failure memo, so any uncovered position read "failed" — a final answer that ends the player's poll, even with the full pass about to deliver, and one any account could plant with an absurd `at`. It now marks only the span it failed to read; "failed" is given once the full pass AND a window there have both failed. - Windows join by what they COVER, not a bucketed identity: a backward seek no longer waits behind a window that cannot cover it, and a playhead crossing a bucket edge no longer queues a second read. The queue is bounded per track and overall. - shutdown() sets a flag a worker checks before it spawns ffmpeg (one still in its Plex lookup used to start a read after the kill sweep); queued-job cancellation and the lifespan call are now tested. - A window starts where ffmpeg is told to seek (rounded to the ms it gets), a rounded-up millisecond carries into the minute (no more `00:00:60.000`), a key's first publish claims nothing before its VTT lands, and `at`/`offset`/`start`/`aoff` refuse non-finite values (`at` also an absurd one).
This commit is contained in:
@@ -18,6 +18,8 @@ behind an unrelated pass). Pure — no Postgres, no ffmpeg (the auth half is in
|
||||
test_plex_subtitle_auth.py, which needs the DB).
|
||||
"""
|
||||
|
||||
import asyncio
|
||||
import shutil
|
||||
import subprocess
|
||||
import sys
|
||||
import threading
|
||||
@@ -30,10 +32,13 @@ import pytest
|
||||
from fastapi.testclient import TestClient
|
||||
|
||||
import app.state as app_state
|
||||
import app.main as app_main
|
||||
from app.auth import current_user
|
||||
from app.main import app
|
||||
from app.plex import subtitles
|
||||
|
||||
needs_ffmpeg = pytest.mark.skipif(shutil.which("ffmpeg") is None, reason="ffmpeg not available")
|
||||
|
||||
|
||||
@pytest.fixture(autouse=True)
|
||||
def _isolated_cache(tmp_path, monkeypatch):
|
||||
@@ -373,14 +378,19 @@ def test_one_window_publishes_every_embedded_text_track_at_absolute_time(monkeyp
|
||||
def test_a_full_pass_that_died_is_not_cached_as_the_whole_track(monkeypatch):
|
||||
"""A truncated full pass used to be published as complete: `ensure` answered "ready" forever, the
|
||||
player stopped polling, and — the cache has no eviction — the subtitles simply ended wherever
|
||||
ffmpeg had died, in every later session too. Now it covers what it provably reached, and the
|
||||
rest of the film honestly reads as failed."""
|
||||
ffmpeg had died, in every later session too. Now it covers what it provably reached; past that
|
||||
a window is tried, and only when that fails too is the position answered as failed."""
|
||||
_stub_item(monkeypatch, clean=False, cues=("39:58.000", "40:00.000"))
|
||||
monkeypatch.setattr(subtitles, "_POOL", _ManualPool())
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
subtitles._extract_and_publish("98614", 3, None)
|
||||
key = subtitles.cache_key("98614", 3)
|
||||
assert subtitles.read_meta(key) == ([[0.0, 2400.0]], False)
|
||||
assert subtitles.ensure("98614", 3, at=100.0)["state"] == "partial"
|
||||
assert subtitles.ensure("98614", 3, at=3000.0)["state"] == "preparing"
|
||||
assert [a[3] for _, a in pool.jobs] == [2970.0], "a window past the break — not the full pass"
|
||||
_window_raises(monkeypatch)
|
||||
pool.run_all()
|
||||
after = subtitles.ensure("98614", 3, at=3000.0)
|
||||
assert (after["state"], after["code"]) == ("failed", "extract_failed")
|
||||
|
||||
@@ -430,7 +440,7 @@ def test_a_sidecar_does_not_wait_behind_an_embedded_full_pass(monkeypatch):
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
_stub_item(monkeypatch)
|
||||
subtitles._INFLIGHT.add(("full", "98614")) # an embedded track's full pass is running
|
||||
subtitles._INFLIGHT[("full", "98614")] = None # an embedded track's full pass is running
|
||||
subtitles.ensure("98614", 0, at=600.0)
|
||||
pool.run_all()
|
||||
assert subtitles.ensure("98614", 0, at=600.0)["state"] == "ready"
|
||||
@@ -528,3 +538,254 @@ def test_an_impossible_position_is_rejected(client, monkeypatch, at):
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
assert client.get(f"/api/plex/subtitle/98614/0/status?at={at}").status_code == 422
|
||||
assert pool.jobs == []
|
||||
|
||||
|
||||
@pytest.mark.parametrize("q", ["offset=-inf", "offset=nan", "offset=inf"])
|
||||
def test_an_impossible_offset_is_rejected(client, q):
|
||||
"""The sibling of `at`: `-inf` crashed the shift with a 500, `nan` stacked every cue at 0."""
|
||||
assert client.get(f"/api/plex/subtitle/98614/0?{q}").status_code == 422
|
||||
|
||||
|
||||
def test_an_absurd_position_is_rejected_before_it_reaches_ffmpeg(client, monkeypatch):
|
||||
"""ffmpeg refuses an `-ss` past its int64 microseconds, and that failure was recorded against the
|
||||
TRACK — every other viewer at an uncovered position was told "failed" for a minute."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
assert client.get("/api/plex/subtitle/98614/0/status?at=1e13").status_code == 422
|
||||
assert pool.jobs == []
|
||||
|
||||
|
||||
# --- the second deep-review round ---------------------------------------------------------------
|
||||
|
||||
|
||||
def _window_raises(monkeypatch):
|
||||
"""From here on every window read fails outright; a full pass still works."""
|
||||
real = subtitles._ffmpeg_extract
|
||||
|
||||
def _extract(src, emb_ords, start, length):
|
||||
if length is not None:
|
||||
raise subtitles.SubtitleUnavailable("extract_failed")
|
||||
return real(src, emb_ords, start, length)
|
||||
|
||||
monkeypatch.setattr(subtitles, "_ffmpeg_extract", _extract)
|
||||
|
||||
|
||||
def _later(monkeypatch, seconds: float) -> None:
|
||||
"""Move the module's clock forward (the failure memos are monotonic-time TTLs)."""
|
||||
now = time.monotonic() + seconds
|
||||
monkeypatch.setattr(subtitles.time, "monotonic", lambda: now)
|
||||
|
||||
|
||||
def test_a_full_pass_that_failed_is_not_read_again_while_its_output_is_watched(monkeypatch):
|
||||
"""Published as partial, a failed full pass left the viewer inside what it DID publish — so the
|
||||
status said `partial`, the poll kept going, and each time the one-minute failure memo lapsed it
|
||||
re-armed a read of the whole container. A failure that reproduces did so every time: a full
|
||||
read of the file every few minutes for as long as they watched."""
|
||||
_stub_item(monkeypatch, clean=False, cues=("39:58.000", "40:00.000"))
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
subtitles._extract_and_publish("98614", 3, None)
|
||||
_later(monkeypatch, subtitles.FAIL_TTL_S + 1)
|
||||
for _ in range(3):
|
||||
assert subtitles.ensure("98614", 3, at=100.0)["state"] == "partial"
|
||||
assert pool.jobs == [], "a failed full pass was queued again"
|
||||
|
||||
|
||||
def test_a_failed_window_does_not_end_the_poll_while_the_full_pass_may_cover_it(monkeypatch):
|
||||
""" "failed" is final — the player stops asking. A window that failed used to set the TRACK's
|
||||
failure memo, so a viewer anywhere outside the covered part got "failed" and never heard about
|
||||
the full pass that landed a minute later."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
_stub_item(monkeypatch)
|
||||
_window_raises(monkeypatch)
|
||||
subtitles.ensure("98614", 3, at=3000.0)
|
||||
pool.run_next() # the window fails; the full pass is still queued behind it
|
||||
assert subtitles.ensure("98614", 3, at=3000.0)["state"] == "preparing"
|
||||
assert subtitles.ensure("98614", 3, at=500.0)["state"] == "preparing"
|
||||
assert [a[3] for _, a in pool.jobs] == [None, 470.0], "the failed stretch was not tried again"
|
||||
|
||||
|
||||
def test_a_backward_seek_gets_its_own_window(monkeypatch):
|
||||
"""A window bucketed by position joined a seek back to 6:40 onto a running window at 9:10 that
|
||||
could not cover it — the right one waited for the wrong one."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
subtitles.ensure("98614", 1, at=580.0)
|
||||
subtitles.ensure("98614", 1, at=400.0)
|
||||
assert sorted(a[3] for _, a in pool.jobs if a[3] is not None) == [370.0, 550.0]
|
||||
|
||||
|
||||
def test_a_playhead_crossing_a_bucket_edge_joins_the_window_that_covers_it(monkeypatch):
|
||||
"""…and the same bucketing queued a second read when a playhead crossed an edge while the first
|
||||
window — which already covered it — was still running."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
for at in (628.0, 629.0, 630.0, 631.0, 632.0):
|
||||
subtitles.ensure("98614", 1, at=at)
|
||||
assert len(pool.jobs) == 2, "one window + the one full pass"
|
||||
|
||||
|
||||
def test_a_scrubbing_viewer_cannot_queue_a_window_per_stop(monkeypatch):
|
||||
"""The pool's queue is unbounded and every job is a read of the library."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
for at in (0.0, 1000.0, 2000.0, 3000.0, 4000.0):
|
||||
subtitles.ensure("98614", 1, at=at)
|
||||
assert len([1 for _, a in pool.jobs if a[3] is not None]) == subtitles._MAX_TRACK_WINDOWS
|
||||
|
||||
|
||||
def test_nothing_more_is_queued_while_the_extractor_is_saturated(monkeypatch):
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
for rk in range(20):
|
||||
subtitles.ensure(str(rk), 0, at=0.0)
|
||||
assert len(pool.jobs) == subtitles._MAX_INFLIGHT
|
||||
|
||||
|
||||
def test_a_window_starts_where_ffmpeg_is_told_to_seek(monkeypatch):
|
||||
"""ffmpeg gets `-ss` to the millisecond, and its cues come back on THAT zero. Shifted back by an
|
||||
unrounded start they landed up to half a millisecond off the full pass's — spelled differently,
|
||||
and so kept twice by the merge."""
|
||||
pool = _ManualPool()
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
subtitles.ensure("98614", 1, at=1198.4375)
|
||||
(window_start,) = [a[3] for _, a in pool.jobs if a[3] is not None]
|
||||
assert window_start == 1168.438
|
||||
|
||||
|
||||
def test_a_millisecond_rounded_up_carries_into_the_minute():
|
||||
"""`00:00:60.000` is not a WebVTT timestamp — the browser drops the cue."""
|
||||
assert subtitles._vtt_s_to_ts(59.9996) == "00:01:00.000"
|
||||
assert subtitles._vtt_s_to_ts(3599.9996) == "01:00:00.000"
|
||||
shifted = subtitles.shift_vtt(_vtt(_cue("00:01:00.000", "00:01:02.000", "x")), 0.0004)
|
||||
assert "00:01:00.000 --> 00:01:02.000" in shifted, shifted
|
||||
|
||||
|
||||
def test_ffmpegs_spelling_of_a_negative_time_reads_exactly():
|
||||
"""With `-avoid_negative_ts disabled` a cue already running at the window's start comes out
|
||||
before zero, and ffmpeg's muxer puts the sign on every field."""
|
||||
assert subtitles._vtt_ts_to_s("00:-5.-05") == pytest.approx(-5.005)
|
||||
assert subtitles._vtt_ts_to_s("-1:-5.-300") == pytest.approx(-65.3)
|
||||
|
||||
|
||||
def test_dying_between_the_two_renames_cannot_pass_a_window_off_as_the_whole_track(monkeypatch):
|
||||
"""A VTT without a sidecar is how an older build cached a COMPLETE track. A publish is two
|
||||
renames, the VTT first — so dying between them on a key's first publish left a window that
|
||||
read as complete, "ready" for good."""
|
||||
key = subtitles.cache_key("98614", 0)
|
||||
real_write = subtitles.cache_write
|
||||
|
||||
def _die_after(k, vtt):
|
||||
real_write(k, vtt)
|
||||
raise KeyboardInterrupt # the process goes away right after the VTT landed
|
||||
|
||||
monkeypatch.setattr(subtitles, "cache_write", _die_after)
|
||||
with pytest.raises(KeyboardInterrupt):
|
||||
subtitles.publish(key, _vtt(_cue("10:00.000", "10:02.000", "x")), (570.0, 900.0), False)
|
||||
assert subtitles.read_meta(key) == ([], False)
|
||||
|
||||
|
||||
def test_shutdown_drops_queued_extractions(monkeypatch):
|
||||
"""Only the kill half used to be pinned. A job still QUEUED at shutdown would otherwise start
|
||||
after the kill sweep — a fresh read of the file holding the process open."""
|
||||
pool = ThreadPoolExecutor(max_workers=1)
|
||||
monkeypatch.setattr(subtitles, "_POOL", pool)
|
||||
busy, release, ran = threading.Event(), threading.Event(), threading.Event()
|
||||
pool.submit(lambda: (busy.set(), release.wait(timeout=5)))
|
||||
pool.submit(ran.set)
|
||||
assert busy.wait(timeout=5)
|
||||
subtitles.shutdown()
|
||||
release.set()
|
||||
pool.shutdown(wait=True)
|
||||
assert not ran.is_set(), "a queued extraction ran after shutdown"
|
||||
|
||||
|
||||
def test_a_worker_that_reaches_ffmpeg_after_shutdown_never_starts_it(monkeypatch):
|
||||
"""A worker still in its Plex lookup when the kill sweep ran used to start its ffmpeg anyway."""
|
||||
monkeypatch.setattr(subtitles, "_POOL", ThreadPoolExecutor(max_workers=1))
|
||||
started: list = []
|
||||
monkeypatch.setattr(subtitles.subprocess, "Popen", lambda cmd, **kw: started.append(cmd))
|
||||
subtitles.shutdown()
|
||||
with pytest.raises(subtitles.SubtitleUnavailable):
|
||||
subtitles._ffmpeg_extract("/plex-media/f.mkv", [0], None, None)
|
||||
assert started == []
|
||||
|
||||
|
||||
def test_the_app_stops_the_extractor_when_it_shuts_down(monkeypatch):
|
||||
"""No test ran the lifespan, so deleting this one call switched all of the above off with every
|
||||
lane green."""
|
||||
|
||||
class _Configured:
|
||||
def __enter__(self):
|
||||
return None
|
||||
|
||||
def __exit__(self, *exc):
|
||||
return False
|
||||
|
||||
async def _no_sweep():
|
||||
return None
|
||||
|
||||
calls: list[str] = []
|
||||
monkeypatch.setattr(app_main, "SessionLocal", _Configured)
|
||||
monkeypatch.setattr(app_main.state, "is_configured", lambda db: True)
|
||||
monkeypatch.setattr(app_main, "_sweep_hls_orphans", _no_sweep)
|
||||
monkeypatch.setattr(app_main, "start_scheduler", lambda: None)
|
||||
monkeypatch.setattr(app_main, "shutdown_scheduler", lambda: None)
|
||||
monkeypatch.setattr(app_main.plex_subtitles, "shutdown", lambda: calls.append("stopped"))
|
||||
|
||||
async def _cycle():
|
||||
async with app_main.lifespan(app):
|
||||
pass
|
||||
|
||||
asyncio.run(_cycle())
|
||||
assert calls == ["stopped"]
|
||||
|
||||
|
||||
# --- a window against a REAL ffmpeg -------------------------------------------------------------
|
||||
|
||||
|
||||
def _make_mkv(tmp_path: Path) -> Path:
|
||||
"""A minute of video with a keyframe every 10 s and a subtitle every 2 s — so a seek to 21.3 s
|
||||
lands on the keyframe at 20 s, with the 20.0–21.5 s cue already running at the window's start."""
|
||||
srt = tmp_path / "s.srt"
|
||||
srt.write_text(
|
||||
"".join(
|
||||
f"{i + 1}\n00:00:{2 * i:02d},000 --> 00:00:{2 * i + 1:02d},500\nline {i}\n\n"
|
||||
for i in range(30)
|
||||
),
|
||||
"utf-8",
|
||||
)
|
||||
out = tmp_path / "f.mkv"
|
||||
subprocess.run(
|
||||
[
|
||||
"ffmpeg", "-nostdin", "-loglevel", "error",
|
||||
"-f", "lavfi", "-i", "color=c=black:s=32x32:r=10:d=60",
|
||||
"-i", str(srt),
|
||||
"-map", "0:v", "-map", "1:s", "-c:v", "mpeg4", "-g", "100", "-c:s", "srt",
|
||||
"-y", str(out),
|
||||
],
|
||||
check=True,
|
||||
) # fmt: skip
|
||||
return out
|
||||
|
||||
|
||||
@needs_ffmpeg
|
||||
def test_a_window_lines_up_with_the_full_pass_on_a_real_file(tmp_path, monkeypatch):
|
||||
"""THE late-and-doubled window. The input seek lands on the keyframe before the window's start,
|
||||
a cue already running there comes out at a negative time, and by default ffmpeg's muxer shifted
|
||||
the whole window so that cue sat at 0 — every cue late by the distance to the keyframe (1–5 s on
|
||||
a real library file), and kept twice for good once the full pass merged in beside it."""
|
||||
src = _make_mkv(tmp_path)
|
||||
monkeypatch.setattr(subtitles, "CACHE_DIR", tmp_path / "cache")
|
||||
full, clean = subtitles._ffmpeg_extract(str(src), [0], None, None)
|
||||
assert clean
|
||||
win, clean = subtitles._ffmpeg_extract(str(src), [0], 21.3, 20.0)
|
||||
assert clean
|
||||
key = subtitles.cache_key("1", 0)
|
||||
subtitles.publish(key, subtitles.shift_vtt(win[0], -21.3), (21.3, 41.3), False)
|
||||
served = subtitles.cache_read(key) or ""
|
||||
assert "00:00:22.000 --> 00:00:23.500\nline 11" in served, served # on time, not 1.3 s late
|
||||
subtitles.publish(key, full[0], (0.0, subtitles._FULL_END_S), True)
|
||||
merged = subtitles.cache_read(key) or ""
|
||||
assert merged.count("-->") == 30, "a window cue survived beside its full-pass twin"
|
||||
|
||||
Reference in New Issue
Block a user