From e2362e1ed1959fd582c78585e524ac5d8d46d3db Mon Sep 17 00:00:00 2001 From: npeter83 Date: Tue, 18 Aug 2026 21:34:36 +0200 Subject: [PATCH] fix(downloads): heartbeat a slow re-encode so the stall watchdog can't false-kill it (E3 S2, B-sub-4) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The supervisor kills a job that writes nothing for download_stall_timeout_seconds (150s) and labels it a "network" stall. But the ffmpeg progress writer only wrote on an integer-percent CHANGE, so a re-encode that sits on one percent for minutes (AV1/VP9 -> H.264 or a crop on the CPU-only prod host) produced no row write and was killed mid-encode as "stalled" — and the retry stalled the same way. Fix: the writer now heartbeats (`_touch_job`, bumping updated_at without touching the progress bar) once per interval even when the whole percent is unchanged, so a live-but-quiet re-encode keeps a fresh updated_at. Reorders the rate-limit gate first so a burst still costs one DB op — either a progress write or a heartbeat. Pure-logic test with an injected clock: three stuck-at-10% intervals write no new progress but heartbeat each time. Full lane green, ruff clean. --- backend/app/worker.py | 9 ++++++++- backend/tests/test_ffmpeg_callbacks.py | 17 +++++++++++++++++ 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/backend/app/worker.py b/backend/app/worker.py index 815c2859..7739cb90 100644 --- a/backend/app/worker.py +++ b/backend/app/worker.py @@ -625,8 +625,15 @@ def _ffmpeg_progress_writer(job_id: int, phase: str, *, now=time.monotonic): state = {"pct": -1} def write(pct: float) -> None: + if not allow(): + return whole = int(pct) - if whole == state["pct"] or not allow(): + if whole == state["pct"]: + # Same integer percent, but ffmpeg IS still working — a slow re-encode (AV1/VP9 -> H.264 + # or a crop on the CPU-only host) can sit on one percent for minutes. Heartbeat the row's + # updated_at so the stall watchdog doesn't kill a live job as "stalled" (B-sub-4), without + # rewriting the unchanged progress bar. + _touch_job(job_id) return state["pct"] = whole _set_job(job_id, progress=whole, phase=phase) diff --git a/backend/tests/test_ffmpeg_callbacks.py b/backend/tests/test_ffmpeg_callbacks.py index d4173b53..9405ef75 100644 --- a/backend/tests/test_ffmpeg_callbacks.py +++ b/backend/tests/test_ffmpeg_callbacks.py @@ -37,12 +37,29 @@ class TestProgressWriter: writes = [] clock = {"t": 1000.0} monkeypatch.setattr(worker, "_set_job", lambda job_id, **f: writes.append(f)) + monkeypatch.setattr(worker, "_touch_job", lambda job_id: None) write = worker._ffmpeg_progress_writer(7, "processing", now=lambda: clock["t"]) write(10.1) clock["t"] += 5 write(10.9) # still 10% — the bar shows integers assert [w["progress"] for w in writes] == [10] + def test_a_slow_same_percent_stretch_heartbeats_the_watchdog(self, monkeypatch): + """B-sub-4: a re-encode that sits on one integer percent for minutes must NOT be killed as + stalled — the writer touches the row (heartbeat) each interval even though it writes no new + progress, so the stall watchdog keeps seeing a fresh updated_at.""" + writes, touches = [], [] + clock = {"t": 1000.0} + monkeypatch.setattr(worker, "_set_job", lambda job_id, **f: writes.append(f)) + monkeypatch.setattr(worker, "_touch_job", lambda job_id: touches.append(job_id)) + write = worker._ffmpeg_progress_writer(7, "processing", now=lambda: clock["t"]) + write(10.1) # first real write → progress 10 + for _ in range(3): # three more intervals stuck on 10% + clock["t"] += 1.5 + write(10.4) + assert [w["progress"] for w in writes] == [10] # progress never rewritten + assert touches == [7, 7, 7] # …but each interval heartbeats the watchdog + class TestCancelPoll: def test_asks_once_then_reuses_the_answer(self, monkeypatch):