fix(api): log ffmpeg stderr when a streamed render fails

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}"'},
     )

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")