Преглед изворни кода

fix(camera): bound the post-kill wait on ffmpeg cleanup (#2580)

After an RTSP read timeout the stream cleanup killed the stalled ffmpeg
and then awaited process.wait() unbounded. A SIGKILLed ffmpeg stuck in
uninterruptible I/O on a dead RTSP socket can take arbitrarily long to
be reaped, so the fan-out stream coroutine sat parked in that wait (12
hours in the reported case) while every new viewer attached to the
stalled broadcaster and received no frames.

Bound the post-kill wait to 2s in all three places it existed: the
stream generator's _terminate_ffmpeg (the reported hang), the camera
stop endpoint (which would hang the recovery request itself; now uses
the shared helper instead of an inline copy), and the orphan-cleanup
janitor (whose hang would disable the safety net). On timeout the
zombie is abandoned; the janitor's /proc scan reaps it next pass and
the stream proceeds to its normal reconnect.
maziggy пре 1 месец
родитељ
комит
75b0175e3d
3 измењених фајлова са 248 додато и 16 уклоњено
  1. 1 0
      CHANGELOG.md
  2. 38 16
      backend/app/api/routes/camera.py
  3. 209 0
      backend/tests/unit/test_camera_ffmpeg_termination.py

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.5b2] - Unreleased
 
 ### Fixed
+- **P2S RTSP timeout could leave the fan-out camera stream permanently stalled (#2580, reported and diagnosed by @ronaldheft, fix shape from PR #2581)** — After an RTSP read timeout, the stream cleanup killed the stalled ffmpeg and then waited *unbounded* for it to be reaped. A SIGKILLed ffmpeg stuck in uninterruptible I/O on a dead RTSP socket can take arbitrarily long to exit, so the fan-out stream coroutine sat parked in that wait — in the reported case for 12 hours — while every new viewer attached to the stalled broadcaster and got no frames (snapshots and diagnostics kept working, since those open fresh connections). The post-kill wait is now bounded (2 s): on timeout the stream abandons the zombie — the orphan janitor's /proc scan reaps it on its next pass — and proceeds to its normal reconnect, so live view recovers by itself. The same unbounded wait hid in two more places, both bounded too: the camera *Stop* endpoint (which would hang the very request a user makes to recover a stuck stream) and the periodic orphan-cleanup janitor itself (which is the safety net that recovers stalled streams, and so can least afford to block).
 - **Queue edit showed the sliced-for model as the scheduler target, and a cross-model queue row could dispatch G-code to an incompatible printer (#2578, reporter @Jostxxl)** — Two bugs with one root. The "Any \<model\>" assignment button labeled itself from the file's slice metadata while the scheduler actually used the row's `target_model`, so an X1C-sliced item targeting H2D read "Any X1C" above "Scheduler will assign to first available idle H2D printer". Worse, the mismatch could be *created* silently: the sliced-for model loads asynchronously, and clicking "Any Model" before it arrived pre-selected the first model alphabetically — on a mixed X1C/P1S/H2D farm that's H2D — after which the model dropdown hid itself, leaving no way to see or fix the wrong target. Nothing downstream checked compatibility, so the scheduler would happily hand X1C G-code to an H2D. Now: the target model is never silently defaulted (the dropdown stays visible in model mode, pre-selected to the sliced-for model when available, and back-fills once the metadata loads); the button reflects the actual target; a warning shows when the target differs from the sliced-for model. Compatibility is enforced end-to-end with an explicit G-code interchange family table (X1/X1C/X1E/P1P/P1S interchange; everything else exact-match — files without slice metadata are never blocked): incompatible models are disabled in the dropdown, queue create/update reject a mismatch with a clear 400 (so API-created rows can't sneak in), and the scheduler holds back pre-existing mismatched rows with an actionable waiting reason instead of dispatching them — fix the target via edit and the job flows again.
 - **Manual jog could drive an axis past its travel limit into a collision (#2579, reporter @R3play210)** — Jog the bed up from Bambuddy and, instead of stopping at the travel limit, it keeps going until the nozzle hits the plate; X/Y overrun too, on every model. Instrumenting the exact bytes sent to an H2D showed Bambuddy issuing a clean, correct move at the limit — `G91` / `G1 Z-1.00 F600` / `G90`, no endstop manipulation — that the printer executed straight past the stop, while the machine's **own touchscreen refuses the identical motion**. **This is a Bambu firmware bug: the firmware does not enforce its soft endstops on G-code received over MQTT** (the path every remote tool, Bambuddy included, must use), and it reports no axis position, so Bambuddy cannot know where the bed is to stop it either. It is not fixable from our side. Two things change here: (1) the jog no longer wraps moves in `M211 S0`/`S1` — the old code disabled the firmware's soft endstops *globally* around every jog, which also broke the **touchscreen's** limits until the printer was power-cycled; it now sends a bare move and never touches `M211`, so the touchscreen stays protected. (2) The jog panel now shows a prominent warning that travel limits are **not** enforced during manual moves because of this firmware bug, so nobody trusts the control to stop at the limit. Client-side travel-limit enforcement (dead-reckoning from a home) is tracked separately as the only real mitigation. If your printer currently overruns even from its touchscreen, power-cycle it once to restore the endstops an older Bambuddy build disabled.
 - **External spool kept its old inventory filament after the type was changed on the printer (#2575, reporter @ajbastien)** — Assigning a new filament to the external spool (e.g. generic ABS in place of generic TPU) left the previous inventory spool assigned, so an ABS spool stayed mapped to TPU. The reconciliation that unlinks a stale external-spool assignment lives in `on_ams_change`, but that callback only fired on changes to the regular AMS units — its change-hash never included the external spool (`vt_tray`/`vir_slot`), and the external-spool data is stored after the AMS handler runs. External-spool identity changes (type, colour, tag, or a reset to empty) now re-trigger the callback so the stale assignment is unlinked; the fill-percentage (`remain`) is deliberately excluded from the fingerprint so a running print doesn't fire it on every push.

+ 38 - 16
backend/app/api/routes/camera.py

@@ -45,6 +45,14 @@ from backend.app.services.camera_profiles import get_camera_profile
 logger = logging.getLogger(__name__)
 router = APIRouter(prefix="/printers", tags=["camera"])
 
+# Upper bound on waiting for a SIGKILLed ffmpeg to be reaped (#2580). A killed
+# ffmpeg stuck in uninterruptible I/O on a dead RTSP socket can take arbitrarily
+# long to exit — an unbounded post-kill wait() parked the fan-out stream
+# coroutine for 12 hours on a P2S, leaving every viewer attached to a stalled
+# broadcaster. Abandoning the wait is safe: cleanup_orphaned_streams' /proc scan
+# reaps any Bambu ffmpeg not attached to an active stream on its next pass.
+_FFMPEG_KILL_TIMEOUT = 2.0
+
 # Track active ffmpeg processes for cleanup
 _active_streams: dict[str, asyncio.subprocess.Process] = {}
 
@@ -243,7 +251,17 @@ async def _terminate_ffmpeg(process: asyncio.subprocess.Process, stream_id: str
         except TimeoutError:
             logger.warning("ffmpeg didn't terminate gracefully, killing (stream_id=%s)", stream_id)
             process.kill()
-            await process.wait()
+            try:
+                await asyncio.wait_for(process.wait(), timeout=_FFMPEG_KILL_TIMEOUT)
+            except TimeoutError:
+                # Do NOT keep waiting (#2580): the caller is the stream
+                # generator, and blocking here pins the fan-out pump forever.
+                # The orphan janitor reaps the process later.
+                logger.error(
+                    "ffmpeg did not exit within %.1fs of SIGKILL; abandoning wait (stream_id=%s)",
+                    _FFMPEG_KILL_TIMEOUT,
+                    stream_id,
+                )
     except ProcessLookupError:
         pass  # Already dead
     except OSError as e:
@@ -829,20 +847,13 @@ async def stop_camera_stream(
             if event:
                 event.set()
             if process.returncode is None:
-                try:
-                    process.terminate()
-                    try:
-                        await asyncio.wait_for(process.wait(), timeout=2.0)
-                    except TimeoutError:
-                        logger.warning("ffmpeg didn't terminate gracefully, killing (stream_id=%s)", stream_id)
-                        process.kill()
-                        await process.wait()
-                    stopped += 1
-                    logger.info("Terminated ffmpeg process for stream %s", stream_id)
-                except ProcessLookupError:
-                    pass  # Process already dead
-                except OSError as e:
-                    logger.warning("Error stopping stream %s: %s", stream_id, e)
+                # Shared helper, not an inline copy: it bounds the post-kill
+                # wait (#2580) — a killed-but-unreaped ffmpeg used to hang this
+                # request forever, exactly when the user hit Stop to recover a
+                # stuck stream.
+                await _terminate_ffmpeg(process, stream_id)
+                stopped += 1
+                logger.info("Terminated ffmpeg process for stream %s", stream_id)
             _spawned_ffmpeg_pids.pop(process.pid, None)
 
     for stream_id in to_remove:
@@ -1615,9 +1626,20 @@ async def cleanup_orphaned_streams():
                 event.set()
             try:
                 proc.kill()
-                await proc.wait()
+                # Bounded (#2580): an unreaped SIGKILLed ffmpeg must not hang
+                # the periodic cleanup loop — this janitor is the safety net
+                # that recovers stalled streams, so it can least afford to
+                # block. The /proc scan above retries the kill next pass.
+                await asyncio.wait_for(proc.wait(), timeout=_FFMPEG_KILL_TIMEOUT)
             except (ProcessLookupError, OSError):
                 pass
+            except TimeoutError:
+                logger.error(
+                    "ffmpeg (pid=%d) did not exit within %.1fs of SIGKILL; abandoning wait (stream_id=%s)",
+                    proc.pid,
+                    _FFMPEG_KILL_TIMEOUT,
+                    sid,
+                )
             _active_streams.pop(sid, None)
             _disconnect_events.pop(sid, None)
             _stream_last_frame_times.pop(sid, None)

+ 209 - 0
backend/tests/unit/test_camera_ffmpeg_termination.py

@@ -0,0 +1,209 @@
+"""Bounded post-kill ffmpeg cleanup (#2580, fix shape from PR #2581 by @ronaldheft).
+
+A SIGKILLed ffmpeg stuck in uninterruptible I/O on a dead RTSP socket can take
+arbitrarily long to be reaped. The cleanup paths used to ``await process.wait()``
+unbounded after ``kill()`` — on a P2S RTSP read timeout this parked the fan-out
+stream coroutine for 12 hours, leaving every viewer attached to a stalled
+broadcaster while snapshots/diagnostics (fresh connections) kept working.
+
+The same unbounded wait existed in THREE places, all bounded now:
+1. ``_terminate_ffmpeg`` — the stream generator's cleanup (the reported hang).
+2. ``stop_camera`` — hung the very request a user makes to recover.
+3. ``cleanup_orphaned_streams`` — hung the janitor that is the safety net.
+"""
+
+from __future__ import annotations
+
+import asyncio
+import time
+from contextlib import suppress
+
+import pytest
+
+from backend.app.api.routes import camera
+
+pytestmark = pytest.mark.asyncio
+
+
+class _FakeServer:
+    def close(self) -> None:
+        pass
+
+    async def wait_closed(self) -> None:
+        pass
+
+
+class _TimeoutReader:
+    """stdout that immediately reports a read timeout (stalled RTSP)."""
+
+    async def read(self, _size: int = -1) -> bytes:
+        raise TimeoutError
+
+
+class _SingleFrameReader:
+    """stdout that yields one complete JPEG then EOF."""
+
+    def __init__(self) -> None:
+        self._sent = False
+
+    async def read(self, _size: int = -1) -> bytes:
+        if self._sent:
+            return b""
+        self._sent = True
+        return b"\xff\xd8fresh-frame\xff\xd9"
+
+
+class _StuckPostKillProcess:
+    """ffmpeg whose post-kill wait() never completes unless cancelled."""
+
+    def __init__(self, pid: int = 41001) -> None:
+        self.pid = pid
+        self.returncode = None
+        self.stdout = _TimeoutReader()
+        self.stderr = None
+        self.wait_calls = 0
+        self.killed = False
+        self.post_kill_wait_cancelled = asyncio.Event()
+        self._release = asyncio.Event()
+
+    def terminate(self) -> None:
+        pass
+
+    def kill(self) -> None:
+        self.killed = True
+
+    async def wait(self) -> int:
+        self.wait_calls += 1
+        if self.wait_calls == 1:
+            # Graceful-terminate window: simulate "didn't exit in time".
+            raise TimeoutError
+        try:
+            await self._release.wait()
+        except asyncio.CancelledError:
+            self.post_kill_wait_cancelled.set()
+            raise
+        self.returncode = -9
+        return self.returncode
+
+
+class _FrameProcess:
+    """Healthy replacement ffmpeg delivering one frame."""
+
+    def __init__(self, pid: int = 41002) -> None:
+        self.pid = pid
+        self.returncode = None
+        self.stdout = _SingleFrameReader()
+        self.stderr = None
+
+    def terminate(self) -> None:
+        pass
+
+    def kill(self) -> None:
+        pass
+
+    async def wait(self) -> int:
+        self.returncode = 0
+        return self.returncode
+
+
+# ---------------------------------------------------------------------------
+# 1. _terminate_ffmpeg — the helper itself is bounded
+# ---------------------------------------------------------------------------
+
+
+async def test_terminate_ffmpeg_abandons_unreaped_kill(monkeypatch):
+    monkeypatch.setattr(camera, "_FFMPEG_KILL_TIMEOUT", 0.05)
+    proc = _StuckPostKillProcess()
+
+    # Must return promptly instead of hanging on the post-kill wait.
+    await asyncio.wait_for(camera._terminate_ffmpeg(proc, "test"), timeout=1.0)
+
+    assert proc.killed is True
+    assert proc.post_kill_wait_cancelled.is_set()
+    assert proc.pid not in camera._spawned_ffmpeg_pids
+
+
+# ---------------------------------------------------------------------------
+# 2. Stream generator — reconnects instead of pinning the fan-out pump
+#    (regression scenario from PR #2581)
+# ---------------------------------------------------------------------------
+
+
+async def test_rtsp_stream_reconnects_past_unreaped_ffmpeg(monkeypatch):
+    """RTSP read timeout → kill hangs → generator must still spawn a fresh
+    ffmpeg and deliver a frame, not block in cleanup forever."""
+    stalled = _StuckPostKillProcess()
+    recovered = _FrameProcess()
+    processes = iter((stalled, recovered))
+    spawned: list[object] = []
+
+    async def fake_create_subprocess_exec(*_args, **_kwargs):
+        process = next(processes)
+        spawned.append(process)
+        return process
+
+    async def fake_create_tls_proxy(_ip_address: str, _port: int):
+        return 48521, _FakeServer()
+
+    monkeypatch.setattr(camera, "get_ffmpeg_path", lambda: "/fake/ffmpeg")
+    monkeypatch.setattr(camera, "create_tls_proxy", fake_create_tls_proxy)
+    monkeypatch.setattr(camera.asyncio, "create_subprocess_exec", fake_create_subprocess_exec)
+    monkeypatch.setattr(camera, "_FFMPEG_KILL_TIMEOUT", 0.01)
+
+    stream = camera.generate_rtsp_mjpeg_stream(
+        ip_address="192.0.2.17",
+        access_code="test-code",
+        model="P2S",
+        fps=15,
+        stream_id="9999-fanout",
+        disconnect_event=asyncio.Event(),
+        printer_id=9999,
+    )
+
+    try:
+        chunk = await asyncio.wait_for(anext(stream), timeout=5.0)
+        assert b"fresh-frame" in chunk
+        assert stalled.killed is True
+        assert stalled.post_kill_wait_cancelled.is_set()
+        assert len(spawned) == 2, "expected a replacement ffmpeg to be spawned"
+    finally:
+        stalled._release.set()
+        with suppress(Exception):
+            await asyncio.wait_for(stream.aclose(), timeout=2.0)
+
+
+# ---------------------------------------------------------------------------
+# 3. Janitor — cleanup_orphaned_streams must not hang on an unreaped process
+# ---------------------------------------------------------------------------
+
+
+async def test_cleanup_orphaned_streams_bounded_on_unreaped_process(monkeypatch):
+    monkeypatch.setattr(camera, "_FFMPEG_KILL_TIMEOUT", 0.05)
+    monkeypatch.setattr(camera, "_scan_bambu_ffmpeg_pids", lambda: [])
+
+    import os
+
+    # Real pid: janitor layer 2 prunes _spawned_ffmpeg_pids entries whose pid
+    # doesn't exist (os.kill(pid, 0)), which would reset the spawn age and
+    # skip the stale-stream kill below.
+    proc = _StuckPostKillProcess(pid=os.getpid())
+    proc.wait_calls = 1  # skip the graceful-terminate branch; janitor kills directly
+    sid = "9998-fanout"
+    now = time.time()
+    camera._active_streams[sid] = proc
+    camera._spawned_ffmpeg_pids[proc.pid] = now - 120  # spawned long ago
+    camera._stream_last_frame_times[sid] = now - 60  # stale: no frames >30s
+
+    try:
+        # Must complete despite proc.wait() never returning.
+        await asyncio.wait_for(camera.cleanup_orphaned_streams(), timeout=2.0)
+
+        assert proc.killed is True
+        assert sid not in camera._active_streams
+        assert proc.pid not in camera._spawned_ffmpeg_pids
+    finally:
+        proc._release.set()
+        camera._active_streams.pop(sid, None)
+        camera._spawned_ffmpeg_pids.pop(proc.pid, None)
+        camera._stream_last_frame_times.pop(sid, None)
+        camera._disconnect_events.pop(sid, None)