fix(camera): drain ffmpeg's pipes during teardown (#NNNN)

Closing a camera view logged "ffmpeg didn't terminate gracefully,
killing" followed by "ffmpeg did not exit within 2.0s of SIGKILL;
abandoning wait", on every single close. Both waits expired every time,
so teardown took a fixed 4.00s -- and since the firmware allows one
camera connection, that was 4s in which nothing else could use it.

ffmpeg is spawned with stdout and stderr as pipes and the teardown paths
have stopped reading them, so it sits blocked in write() on a full 64 KiB
pipe. SIGTERM cannot be acted on there: the handler only sets a flag that
the main loop polls, and the loop never gets back to the check. SIGKILL
does kill it, but asyncio resolves Process.wait()'s waiter through
_try_finish(), which requires every pipe transport to report
disconnected; paused, unread pipes never reach EOF, so wait() blocks with
returncode already set. A negative-control test shows returncode=-9 at
the instant the abandon fires.

Draining both pipes while stopping the process fixes both halves: 4.00s
becomes ~0.15s. The signal ladder and its bounds stay as backstops, so a
genuinely wedged process still cannot hang a stream, a Stop request or
the janitor.

This corrects _FFMPEG_KILL_TIMEOUT's premise and #2580's conclusion. That
12-hour hang was the unbounded form of this same self-inflicted stall, not
an ffmpeg stuck in uninterruptible I/O -- the process observed doing it
was in state S, which cannot survive a delivered SIGKILL. Bounding the
wait capped the symptom without removing the cause.

CHANGELOG.md

@@ -24,6 +24,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **Debug logs now record what the printer reports between the last layer and the end of a print (#2547, reporter @anthonyma94)** — The finish photo wants a moment that Bambu firmware does not obviously announce: printing done, toolhead parked, filament unload not yet started. Bambuddy has been driving that capture from `stg_cur=22` ("Filament unloading"), which turns out to fire on no model at all — across 247 support bundles there is not a single stage-22 capture, including the window in which it was the only trigger in the code, where all 104 captures on A1, A1 Mini, H2C, H2D, P1S, P2S, X1C and X2D fell through to the after-the-fact fallback. Choosing a replacement was not possible from the bundles we had, because outside `stg_cur` and `mc_print_sub_stage` every stage and action field the printers send is dropped unread, and the most promising candidates (`print_real_action`, `mc_action`, `mc_stage`) are absent from A1, A1 Mini and P1S payloads entirely. With debug logging enabled, Bambuddy now dumps those raw fields for the window between the last object layer and the end of the print — opening on the first end-of-print signal (last layer reached, progress at 99+, or no remaining time), logging only what changed frame to frame, and closing on the state transition — so a single debug bundle per model can show whether any firmware marks that moment. Diagnostics only: nothing reads these values, they are printer telemetry with nothing identifying in them, and at normal log levels the probe does no work at all. Covered by tests for the window boundaries, the frame budget and the guarantee that the probe cannot break status ingest.
 
 ### Fixed
+- **Closing the camera held the printer's camera connection for four more seconds, then logged an error that wasn't true (#NNNN)** — Every time a camera view closed, the log recorded `ffmpeg didn't terminate gracefully, killing` and then `ffmpeg did not exit within 2.0s of SIGKILL; abandoning wait`. Both waits expired every single time, so each close cost a fixed four seconds — and because Bambu firmware allows exactly one camera connection, that was four seconds in which nothing else could use the camera: reopening the view, a snapshot, Obico, or the diagnostic. **Root cause.** ffmpeg is started with its output and error streams as pipes, and the shutdown path had stopped reading them. A process whose output pipe is full blocks mid-write, and ffmpeg's shutdown signal only sets a flag that its main loop checks on the next pass, so the polite request could never be acted on and the grace period was dead time. The forced kill did work — but Python cannot report an exit while a pipe is still unread, so the second wait expired too and Bambuddy concluded the process was stuck when it had already gone. Measured at 4.00s per close before, ~0.15s after. **Fix.** Both pipes are now drained while the process is being stopped, which makes the polite shutdown effective and the exit observable. The forced-kill path and its time limit remain as backstops, so a genuinely wedged process still can't hang a stream, a Stop request, or the cleanup task. This also corrects the conclusion recorded for #2580: that 12-hour hang was the unbounded form of this same self-inflicted stall rather than a stuck ffmpeg, so bounding the wait had capped the symptom without removing the cause. Covered by tests that drive a real subprocess — the fault lives in Python's pipe bookkeeping, so a stand-in object would pass against the broken code — including one that verifies a process ignoring the polite signal still has its forced exit observed rather than abandoned.
 - **Two snapshots taken at the same moment opened two competing camera connections (#2705, reporter @gzimbric)** — Bambu firmware allows exactly one camera connection at a time. Bambuddy already knew this: a snapshot taken while somebody is watching the live view reuses the viewer's frame instead of opening a second socket. What nothing covered was two *snapshots* overlapping with no viewer attached at all — an Obico poll and a printer-wall refresh landing 200 ms apart, each correctly concluding it wasn't competing with a viewer, and then colliding with each other. On the reporter's P2S this knocked over the live stream that was feeding the camera wall, which was then reaped for having received no frames for 58 seconds. Eight paths take one-shot frames independently — Obico polling, `/camera/snapshot`, the finish-photo capture and its disk-writing sibling, plate detection, the camera connection test, and the diagnostic — so any pair of them could overlap, and a shorter Obico interval widened the window. **Fix.** Simultaneous captures for the same printer now share one connection: the first opens it, everyone arriving while it is in flight gets the same frame. Every consumer here wants "a recent frame" rather than a frame stamped at its own microsecond, so identical bytes are the right answer. This shares captures, it does not cache them — a request arriving after the previous capture finished still takes a fresh frame, because plate detection and the finish photo judge a running print from these images and a stale frame there is worse than a slow one. Each caller keeps its own deadline (they range from 10 to 30 seconds) rather than inheriting whichever one happened to open the connection, giving up alone leaves the capture running for whoever else is waiting on it, and a capture that fails doesn't hand its failure to callers that never got an attempt of their own — they retry, which by then competes with nothing. One visible consequence: when the **Diagnose** tool shares a capture this way its frame-capture stage is labelled `coalesced_capture`, because the pass is real but the timing shown is mostly time spent waiting, and a diagnostic must not report on a connection it never opened. Wiki updated. Covered by tests for the reported collision, the five-callers-one-connection case the reporter verified on live hardware, per-printer isolation, staying coalescing rather than becoming a cache, registry cleanup, a failed capture not poisoning its followers, bounded retry, a follower abandoning its wait without sabotaging the capture, and cancellation from either side.
 - **Auto-matched filament showed a green tick when the colour was plainly wrong (#2687, reporter @pchulpjoost)** — The Filament Mapping panel reported a slot as matched, with the header reading **(Ready)**, while the swatch beside it showed the slice wanted dark red and the tray it had picked held Dark Green. Manually selecting that very same tray from the dropdown correctly reported the colour mismatch, which is what made the disagreement so visible. **Root cause.** Auto-match ranks candidate trays by filament preset ID (`tray_info_idx`) first, and when exactly one loaded tray carried the preset the slice asked for, that tray was accepted as a *definitive* match on the assumption "same preset means same spool, so the colour must agree too". The preset ID names the **variant**, not the spool — `GFA00` is PLA Basic, `GFA01` PLA Matte, `GFA17` PLA Translucent, in every colour Bambu sells it. So a user with one Matte spool loaded matched every Matte requirement regardless of colour, and the colour comparison was never reached. This is why the report came in for PLA Matte in particular: generic PLA Basic is usually loaded several times over, which sent the match down a different path that did compare colours correctly. **Fix.** The colour verdict is now taken from the tray that was actually selected, never from which rule selected it, and the automatic and manual paths share one comparison so they cannot drift apart again. The preset still decides *selection*, because the Basic/Matte/Silk distinction matters ([#2650](https://github.com/maziggy/bambuddy/issues/2650)) — a wrong-coloured tray of the right variant is still chosen, but it is now reported as an amber **Color mismatch** instead of a green tick, and you can print anyway or pick another slot. A near-enough shade still counts as a match, and a 3MF that specifies no colour for a slot is satisfied by any colour rather than being flagged. Dispatch behaviour is unchanged: **Force color match** already required an exact colour before sending a job, so nothing was ever printed in the wrong colour because of this — the panel was simply telling you it was fine when it wasn't. Frontend-only. Wiki updated. Covered by tests for the unique-preset wrong-colour case, agreement between the auto and manual verdicts, the near-shade and colourless-requirement cases, and the multi-preset path that already worked.
 - **P1-series archives kept the worse finish photo when the timelapse arrived late (#2704 follow-up)** — When a print records a timelapse, Bambuddy prefers the video's last frame as the finish photo: the firmware stops recording after the toolhead parks but before the end G-code drops the bed, so it frames the finished print properly, where a live camera grab at that moment catches an already-lowered plate. Bambuddy waited 60 seconds for the video and then gave up, because the print-complete notification is waiting on that photo and holding a notification for minutes is worse than sending it with the live grab. On P1-series printers the video usually arrives later than that — they write MJPEG AVI instead of H.264 MP4 and serve it slowly, so across the support bundles their median was 33 seconds but the 90th percentile was 167 and the slowest observed was 546; every other model finished inside 26 seconds. The result was that the printers most in need of the better photo were the ones that never got it. **Fix.** The notification still goes out on the same 60-second bound with the live grab, so nothing gets slower. If the video was still on its way when that bound expired, Bambuddy now keeps waiting in the background and adds the extracted frame to the archive when it lands, at the front of the photo list so opening the gallery shows it first. The live grab is kept rather than replaced — the notification that already went out links to that exact file, and removing it would leave a broken image in Discord or Telegram. Covered by tests for the ordering, the longer budget, idempotency and the cases where the video never arrives.

backend/app/api/routes/camera.py

@@ -46,12 +46,25 @@ 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.
+# Grace period for a SIGTERMed ffmpeg to shut down before we SIGKILL it. Only
+# reachable when ffmpeg genuinely ignores SIGTERM: _terminate_ffmpeg drains the
+# pipes first, and a drained ffmpeg exits in ~0.15s.
+_FFMPEG_TERM_TIMEOUT = 2.0
+
+# Upper bound on waiting for a SIGKILLed ffmpeg to be reaped (#2580).
+#
+# The original diagnosis — "a killed ffmpeg stuck in uninterruptible I/O on a
+# dead RTSP socket" — was wrong, and this bound was capping a deadlock of our
+# own making rather than waiting out a stuck process. A process that survives
+# SIGKILL would have to be in uninterruptible sleep (state D); the ffmpeg seen
+# doing this was in state S, and its returncode was already set to -9 while
+# wait() was still blocked. The real cause was undrained pipes (see
+# _terminate_ffmpeg), which made this timeout fire on *every* camera close.
+#
+# Kept as a backstop now that the cause is fixed: it should no longer be
+# reachable, and if it ever is, abandoning the wait is still safe because
+# 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
@@ -241,14 +254,63 @@ async def generate_chamber_mjpeg_stream(
         logger.info("Chamber image stream stopped for %s (stream_id=%s)", ip_address, stream_id)
 
 
+async def _drain_pipe(reader) -> None:
+    """Read a subprocess pipe to EOF and discard, so it can never block.
+
+    Best-effort by design: any read failure means we cannot drain further, and
+    the caller is tearing the process down regardless.
+    """
+    if reader is None:
+        return
+    try:
+        while await reader.read(65536):
+            pass
+    except asyncio.CancelledError:
+        raise
+    except Exception:  # noqa: BLE001 — teardown must not fail on a dying pipe
+        return
+
+
 async def _terminate_ffmpeg(process: asyncio.subprocess.Process, stream_id: str | None = None) -> None:
-    """Terminate an ffmpeg process gracefully, then kill if needed."""
+    """Terminate an ffmpeg process gracefully, then kill if needed.
+
+    Drains stdout/stderr throughout, which is load-bearing rather than hygiene.
+    ffmpeg is spawned with both as pipes, and every caller of this has already
+    stopped reading stdout — so by the time we get here ffmpeg is typically
+    blocked in write() on a full 64 KiB pipe. Two things then go wrong:
+
+    * SIGTERM cannot be acted on. ffmpeg's handler only sets a flag that its
+      main loop polls, and a loop blocked in write() never reaches the check,
+      so the whole grace period is dead time.
+    * SIGKILL does kill it, but wait() cannot observe that. asyncio resolves
+      Process.wait()'s waiter through BaseSubprocessTransport._try_finish(),
+      which requires every pipe transport to report disconnected; paused,
+      unread pipes never reach EOF, so wait() blocks with returncode already
+      set. That is what made the "did not exit within Ns of SIGKILL" error
+      fire on every single camera close, and unbounded it was the 12-hour
+      hang in #2580.
+
+    Draining fixes both: SIGTERM becomes actionable and the exit observable.
+    Measured on an H2D: 4.0s of dead time per close before, ~0.15s after —
+    which matters because the printer allows exactly one camera connection,
+    so every one of those seconds was a connection nobody could use.
+
+    Discarding what we drain is deliberate. The stream loop already reads
+    stderr on its error paths (_read_ffmpeg_stderr), and it does so before
+    calling this, so nothing diagnostic is lost.
+    """
     if process.returncode is not None:
+        _spawned_ffmpeg_pids.pop(process.pid, None)
         return  # Already dead
+
+    drainers = [
+        asyncio.create_task(_drain_pipe(process.stdout)),
+        asyncio.create_task(_drain_pipe(process.stderr)),
+    ]
     try:
         process.terminate()
         try:
-            await asyncio.wait_for(process.wait(), timeout=2.0)
+            await asyncio.wait_for(process.wait(), timeout=_FFMPEG_TERM_TIMEOUT)
         except TimeoutError:
             logger.warning("ffmpeg didn't terminate gracefully, killing (stream_id=%s)", stream_id)
             process.kill()
@@ -257,7 +319,8 @@ async def _terminate_ffmpeg(process: asyncio.subprocess.Process, stream_id: str
             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.
+                # The orphan janitor reaps the process later. With the pipes
+                # drained this should be unreachable — see _FFMPEG_KILL_TIMEOUT.
                 logger.error(
                     "ffmpeg did not exit within %.1fs of SIGKILL; abandoning wait (stream_id=%s)",
                     _FFMPEG_KILL_TIMEOUT,
@@ -267,7 +330,11 @@ async def _terminate_ffmpeg(process: asyncio.subprocess.Process, stream_id: str
         pass  # Already dead
     except OSError as e:
         logger.warning("Error terminating ffmpeg: %s", e)
-    _spawned_ffmpeg_pids.pop(process.pid, None)
+    finally:
+        for drainer in drainers:
+            drainer.cancel()
+        await asyncio.gather(*drainers, return_exceptions=True)
+        _spawned_ffmpeg_pids.pop(process.pid, None)
 
 
 def _summarize_ffmpeg_stderr(text: str | None) -> str:

backend/tests/unit/test_camera_ffmpeg_termination.py

@@ -1,20 +1,33 @@
-"""Bounded post-kill ffmpeg cleanup (#2580, fix shape from PR #2581 by @ronaldheft).
+"""ffmpeg teardown: draining the pipes, and the bounded waits behind it.
 
-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.
+Originally #2580 (fix shape from PR #2581 by @ronaldheft): the cleanup paths
+``await process.wait()``-ed unbounded after ``kill()``, which on a P2S RTSP read
+timeout parked the fan-out stream coroutine for 12 hours, leaving every viewer
+attached to a stalled broadcaster while snapshots (fresh connections) kept
+working. Three places had it, all bounded now:
 
-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.
+
+That diagnosis — "a SIGKILLed ffmpeg stuck in uninterruptible I/O" — turned out
+to be wrong, and the bound was capping a deadlock of our own making. ffmpeg was
+blocked writing to a stdout pipe nobody was reading, which makes SIGTERM
+unactionable, and ``wait()`` cannot observe an exit while a pipe transport is
+still undrained. So the abandon path fired on every camera close, costing 4s of
+the printer's single camera connection each time. The pipes are drained now; the
+bounds remain as backstops, and the tests for them stay valid.
+
+The draining tests below drive a REAL subprocess, because the failure is in
+asyncio's pipe/transport bookkeeping — a fake process object cannot reproduce
+it and would happily pass against the broken code.
 """
 
 from __future__ import annotations
 
 import asyncio
+import logging
+import sys
 import time
 from contextlib import suppress
 
@@ -24,6 +37,46 @@ from backend.app.api.routes import camera
 
 pytestmark = pytest.mark.asyncio
 
+# Stands in for ffmpeg: floods stdout, and handles SIGTERM the way ffmpeg does
+# — a handler that sets a flag which only the main loop checks, so a process
+# blocked in write() never acts on it until something drains the pipe.
+_FFMPEG_LIKE = """
+import signal, sys
+stop = False
+def _handler(*_a):
+    global stop
+    stop = True
+signal.signal(signal.SIGTERM, _handler)
+sys.stderr.write("x" * 4096)
+sys.stderr.flush()
+while not stop:
+    sys.stdout.buffer.write(b"x" * 65536)
+    sys.stdout.buffer.flush()
+"""
+
+# Same, but SIGTERM is ignored outright — forces the SIGKILL branch.
+_SIGTERM_PROOF = """
+import signal, sys
+signal.signal(signal.SIGTERM, signal.SIG_IGN)
+while True:
+    sys.stdout.buffer.write(b"x" * 65536)
+    sys.stdout.buffer.flush()
+"""
+
+
+async def _spawn(program: str) -> asyncio.subprocess.Process:
+    """Start the stand-in and let it fill its stdout pipe, as the cancel path
+    leaves a real ffmpeg."""
+    process = await asyncio.create_subprocess_exec(
+        sys.executable,
+        "-c",
+        program,
+        stdout=asyncio.subprocess.PIPE,
+        stderr=asyncio.subprocess.PIPE,
+    )
+    await asyncio.sleep(0.4)
+    return process
+
 
 class _FakeServer:
     def close(self) -> None:
@@ -106,6 +159,64 @@ class _FrameProcess:
         return self.returncode
 
 
+# ---------------------------------------------------------------------------
+# 0. _terminate_ffmpeg drains the pipes — against a real subprocess
+# ---------------------------------------------------------------------------
+
+
+async def test_terminate_drains_stdout_so_sigterm_works(caplog):
+    """A process blocked writing to a full pipe still shuts down on SIGTERM.
+
+    Undrained, this took the full grace period plus the SIGKILL bound (4s
+    measured) and ended in the abandon error. Drained, SIGTERM lands.
+    """
+    process = await _spawn(_FFMPEG_LIKE)
+    camera._spawned_ffmpeg_pids[process.pid] = time.time()
+
+    with caplog.at_level(logging.WARNING, logger=camera.logger.name):
+        started = time.monotonic()
+        await asyncio.wait_for(camera._terminate_ffmpeg(process, "test-drain"), timeout=5.0)
+        elapsed = time.monotonic() - started
+
+    assert process.returncode is not None, "wait() must observe the exit"
+    # Comfortably under the 2.0s grace period: proves SIGTERM was acted on
+    # rather than timing out into the kill branch.
+    assert elapsed < 1.5, f"teardown took {elapsed:.2f}s — pipes likely not drained"
+    assert "didn't terminate gracefully" not in caplog.text
+    assert "abandoning wait" not in caplog.text
+    assert process.pid not in camera._spawned_ffmpeg_pids
+
+
+async def test_terminate_observes_kill_of_a_sigterm_proof_process(monkeypatch, caplog):
+    """Even when SIGTERM is genuinely ignored, wait() must see the SIGKILL.
+
+    This is the case the abandon error was invented for. With the pipes drained
+    the exit is observable, so it must not fire.
+    """
+    monkeypatch.setattr(camera, "_FFMPEG_TERM_TIMEOUT", 0.3)
+    process = await _spawn(_SIGTERM_PROOF)
+    camera._spawned_ffmpeg_pids[process.pid] = time.time()
+
+    with caplog.at_level(logging.WARNING, logger=camera.logger.name):
+        await asyncio.wait_for(camera._terminate_ffmpeg(process, "test-kill"), timeout=5.0)
+
+    assert process.returncode == -9, "SIGKILLed exit must be observed, not abandoned"
+    assert "didn't terminate gracefully" in caplog.text  # SIGTERM really was ignored
+    assert "abandoning wait" not in caplog.text
+    assert process.pid not in camera._spawned_ffmpeg_pids
+
+
+async def test_terminate_is_a_noop_for_an_already_dead_process():
+    """The early return must still drop the pid from the tracking dict."""
+    process = await asyncio.create_subprocess_exec(sys.executable, "-c", "pass")
+    await process.wait()
+    camera._spawned_ffmpeg_pids[process.pid] = time.time()
+
+    await asyncio.wait_for(camera._terminate_ffmpeg(process, "test-dead"), timeout=2.0)
+
+    assert process.pid not in camera._spawned_ffmpeg_pids
+
+
 # ---------------------------------------------------------------------------
 # 1. _terminate_ffmpeg — the helper itself is bounded
 # ---------------------------------------------------------------------------

backend/tests/unit/test_camera_usb_stream_cleanup.py

@@ -33,6 +33,10 @@ class _CleanProc:
     def __init__(self, pid: int) -> None:
         self.pid = pid
         self.returncode = None
+        # Real Process objects always expose these (None when not piped), and
+        # _terminate_ffmpeg drains them so a full pipe can't wedge the exit.
+        self.stdout = None
+        self.stderr = None
 
     def terminate(self) -> None:
         self.returncode = 0