From 1dee6d96902df4c3d047dd9e456a74e52e135d70 Mon Sep 17 00:00:00 2001 From: Thales <> Date: Thu, 16 Jul 2026 23:13:38 +0100 Subject: [PATCH] fix(api): log ffmpeg stderr when a streamed render fails Streamed ffmpeg renders (mixdown export, region trims, stem MP3, video mux) sent stderr to DEVNULL. When ffmpeg died mid-stream the client received a truncated file with HTTP 200 already committed -- and no trace of the failure existed anywhere, making "my export is broken" reports unsolvable. stderr is now drained into a bounded tail (mandatory anyway once it is a pipe -- an undrained full pipe would deadlock ffmpeg) and logged at WARNING with a per-endpoint context (job id, format, stems) when the process exits non-zero. Kills we initiated on client disconnect are expected and stay silent; EOF-then-nonzero is the failure signature, since returncode stays None until wait() even for an exited child. Closes #280 --- app/api/stems.py | 52 ++++++++++++++++++++++++++++++++++------- tests/test_stems_api.py | 40 +++++++++++++++++++++++++++++++ 2 files changed, 84 insertions(+), 8 deletions(-) diff --git a/app/api/stems.py b/app/api/stems.py index 2c79987..4523a52 100644 --- a/app/api/stems.py +++ b/app/api/stems.py @@ -8,6 +8,7 @@ import tempfile import uuid import zipfile +from collections import deque from pathlib import Path from fastapi import APIRouter, HTTPException, Query @@ -82,23 +83,58 @@ def _parse_lane_gains(stems: str, gains: str) -> tuple[list[str], list[float]]: return names, parsed_gains -async def _stream_ffmpeg(cmd: list[str]): - """Yield ffmpeg stdout in 64 KB chunks; kill process on client disconnect.""" +async def _drain_stderr(stream: asyncio.StreamReader, sink: deque[str]) -> None: + """Collect ffmpeg stderr lines into a bounded deque. Draining is mandatory + once stderr is a pipe -- an undrained full pipe would deadlock ffmpeg.""" + while True: + line = await stream.readline() + if not line: + return + sink.append(line.decode("utf-8", "replace").rstrip()) + + +async def _stream_ffmpeg(cmd: list[str], context: str = ""): + """Yield ffmpeg stdout in 64 KB chunks; kill process on client disconnect. + + stderr is captured (bounded tail) and logged at WARNING when ffmpeg exits + non-zero (#280): the HTTP status is already committed mid-stream, so a + failed render reaches the client as a truncated file -- the log entry is + the only place the failure can surface. Kills we initiated (client + disconnect) are expected and not logged as failures.""" proc = await asyncio.create_subprocess_exec( *cmd, stdout=asyncio.subprocess.PIPE, - stderr=asyncio.subprocess.DEVNULL, + stderr=asyncio.subprocess.PIPE, ) + stderr_tail: deque[str] = deque(maxlen=30) + drain_task = asyncio.create_task(_drain_stderr(proc.stderr, stderr_tail)) + # Whether stdout reached EOF. proc.returncode stays None until wait() + # reaps the child even after it exited, so EOF -- not returncode -- is + # what distinguishes "ffmpeg finished on its own" from "client + # disconnected mid-stream and we killed it". + finished = False try: while True: chunk = await proc.stdout.read(65536) if not chunk: + finished = True break yield chunk finally: - if proc.returncode is None: + if not finished and proc.returncode is None: proc.kill() await proc.wait() + try: + await asyncio.wait_for(drain_task, timeout=5) + except (TimeoutError, asyncio.TimeoutError): + drain_task.cancel() + if finished and proc.returncode != 0: + logger.warning( + "stream ffmpeg exit %s [%s]: %s", + proc.returncode, + context, + " | ".join(list(stderr_tail)[-8:]) or "(no stderr)", + ) async def _ensure_cached_mp3(src: Path) -> Path: @@ -200,7 +236,7 @@ async def get_stem( "pipe:1", ] return StreamingResponse( - _stream_ffmpeg(cmd), + _stream_ffmpeg(cmd, context=f"stem-region job={job_id} stem={name}"), media_type="audio/wav", headers={"Content-Disposition": f'attachment; filename="{name}_region.wav"'}, ) @@ -258,7 +294,7 @@ async def get_stem_mp3( ] filename = f"{name}_region.mp3" if start is not None else f"{name}.mp3" return StreamingResponse( - _stream_ffmpeg(cmd), + _stream_ffmpeg(cmd, context=f"stem-mp3 job={job_id} stem={name}"), media_type="audio/mpeg", headers={"Content-Disposition": f'attachment; filename="{filename}"'}, ) @@ -325,7 +361,7 @@ async def get_mixdown( media_type = MIXDOWN_MEDIA_TYPES[ext] return StreamingResponse( - _stream_ffmpeg(cmd), + _stream_ffmpeg(cmd, context=f"mixdown job={job_id} ext={ext} stems={stems}"), media_type=media_type, headers={"Content-Disposition": f'attachment; filename="mixdown.{ext}"'}, ) @@ -405,7 +441,7 @@ async def get_video_mixdown( filename = f"{_safe_title(job.title)}_video.mp4" return StreamingResponse( - _stream_ffmpeg(cmd), + _stream_ffmpeg(cmd, context=f"video-mux job={job_id} stems={stems}"), media_type="video/mp4", headers={"Content-Disposition": f'attachment; filename="{filename}"'}, ) diff --git a/tests/test_stems_api.py b/tests/test_stems_api.py index 2da2a6a..da174d2 100644 --- a/tests/test_stems_api.py +++ b/tests/test_stems_api.py @@ -379,6 +379,46 @@ def test_mixdown_honors_export_sample_rate(client, tmp_path, monkeypatch): assert int.from_bytes(r.content[24:28], "little") == 48000 +@pytest.mark.asyncio +async def test_stream_ffmpeg_logs_stderr_on_failure(caplog): + """#280: a mid-stream ffmpeg failure can't change the HTTP status, so the + stderr tail must land in the log -- previously it went to DEVNULL and a + corrupt download left no trace anywhere.""" + import logging + import sys + + from app.api.stems import _stream_ffmpeg + + cmd = [ + sys.executable, + "-c", + "import sys; sys.stdout.write('partial-bytes'); sys.stdout.flush();" + " sys.stderr.write('boom: encoder exploded\\n'); sys.exit(2)", + ] + with caplog.at_level(logging.WARNING, logger="stemdeck.api"): + chunks = [c async for c in _stream_ffmpeg(cmd, context="mixdown job=test ext=wav")] + + assert b"".join(chunks) == b"partial-bytes" # stream still delivered + warning = next(r.message for r in caplog.records if "stream ffmpeg exit" in r.message) + assert "mixdown job=test ext=wav" in warning + assert "boom: encoder exploded" in warning + + +@pytest.mark.asyncio +async def test_stream_ffmpeg_clean_exit_logs_nothing(caplog): + import logging + import sys + + from app.api.stems import _stream_ffmpeg + + cmd = [sys.executable, "-c", "import sys; sys.stdout.write('ok')"] + with caplog.at_level(logging.WARNING, logger="stemdeck.api"): + chunks = [c async for c in _stream_ffmpeg(cmd, context="happy")] + + assert b"".join(chunks) == b"ok" + assert not [r for r in caplog.records if "stream ffmpeg exit" in r.message] + + def test_mixdown_rejects_unknown_ext_still(client): # ogg remains unsupported even after adding flac. r = client.get("/api/jobs/abcdef000001/mixdown.ogg?stems=vocals&gains=1")