fix(camera): capture ffmpeg stderr when an RTSP stream stalls (#1395)

A P2S support bundle on 0.2.5b1 — per-model probesize fix already
  applied — showed the camera still failing: ffmpeg connects, stays alive
  30+ seconds, emits zero JPEG bytes, the 30s stdout.read times out,
  reconnect loop repeats. No ffmpeg stderr appeared anywhere in the log to
  explain why.

  The cause was a diagnostic bug, not the camera path. _read_ffmpeg_stderr
  called process.stderr.read() — read-to-EOF. A stalled-but-still-alive
  ffmpeg (the P2S RTSP failure mode) never closes stderr, so the read
  blocked until the 2s wait_for timeout and returned None, discarding the
  banner + stream-analysis lines ffmpeg had already printed. ffmpeg stderr
  was captured only when it fully exited; once the probesize bump turned
  the earlier crash into a hang, the diagnostic went dark.

  Drain stderr incrementally in bounded 8KB chunks (64KB cap), returning
  whatever ffmpeg printed so far whether or not it has exited. Also log
  the resolved per-model probesize/analyzeduration on the info-level
  "Starting RTSP camera stream" line, and log the full ffmpeg argv at
  debug level with only the credential-bearing camera URL redacted
  instead of hiding the entire command.

  No behaviour change to streaming — this makes the unresolved P2S RTSP
  stall diagnosable in the next support bundle.
This commit is contained in:
maziggy
2026-05-22 10:02:41 +02:00
parent 51b0d28b05
commit 056f06a396
3 changed files with 91 additions and 11 deletions
+1
View File
@@ -20,6 +20,7 @@ All notable changes to Bambuddy will be documented in this file.
- **PyJWT CVE-2025-45768 (PYSEC-2025-183 / GHSA-65pc-fj4g-8rjx): permanently ignored in pip-audit** — Advisory is disputed by the PyJWT maintainers, with the advisory description literally noting *"this is disputed by the Supplier because the key length is chosen by the application that uses the library."* `fix_versions=[]` on the advisory confirms no PyJWT patch exists or will exist. Bambuddy is not affected: `backend/app/core/auth.py:184` auto-generates secrets via `secrets.token_urlsafe(64)` (~86 chars of entropy, far above any sane minimum) and the file-loaded path at `:177` rejects secrets shorter than 32 chars. Added a permanent `--ignore-vuln CVE-2025-45768` to `.github/workflows/security.yml` with an inline comment citing the file:line evidence so a future maintainer reviewing the ignore list sees why it's load-bearing. Also dropped the stale `--ignore-vuln CVE-2026-4539` for Pygments — Pygments has since shipped a patched version and the ignore is no longer load-bearing (verified: `pip-audit --ignore-vuln CVE-2025-45768` alone reports clean).
### Fixed
- **Camera: ffmpeg's stderr is now captured when an RTSP stream stalls instead of only when ffmpeg crashes (#1395, reported by @Tschipel)** — A P2S support bundle taken on 0.2.5b1 (the per-model probesize fix already applied) showed the camera still failing: ffmpeg connects, stays alive 30+ seconds, emits zero JPEG bytes, the stream's 30 s `stdout.read` times out, reconnect loop repeats — but with **no ffmpeg stderr anywhere in the log** to say why. Root cause was a diagnostic bug, not the camera path: `_read_ffmpeg_stderr` called `process.stderr.read()` (read-to-EOF). A stalled-but-still-alive ffmpeg — exactly the P2S RTSP failure mode — never closes stderr, so the read blocked until the 2 s `wait_for` timeout and returned `None`, discarding the banner + stream-analysis lines ffmpeg had already printed. ffmpeg's stderr was therefore captured *only* when it fully exited; the earlier "not enough frames to estimate rate" smoking gun was available only because ffmpeg crashed back then, and once the probesize bump turned the crash into a hang the diagnostic went dark. **Fix**: `_read_ffmpeg_stderr` now drains stderr incrementally in bounded 8 KB chunks (64 KB cap), returning whatever ffmpeg has printed so far whether or not it has exited — so a hung stream is self-describing in the next support bundle. Additionally, `generate_rtsp_mjpeg_stream` now logs the resolved per-model `probesize` / `analyzeduration` on the info-level "Starting RTSP camera stream" line (verifiable without debug logging), and the debug-level ffmpeg-command line logs the full argv with only the credential-bearing camera URL redacted, instead of hiding the entire command. No behaviour change to streaming itself — this makes the still-unresolved P2S RTSP stall diagnosable. **Tests**: 4 new in `test_camera_stderr_summary.py` cover `_read_ffmpeg_stderr` capturing output from a *running* (un-exited, no-EOF) ffmpeg — the regression — as well as the exited case, the no-stderr-pipe case, and banner-only output summarizing to `None`. 9 camera-stderr tests green; backend ruff clean.
- **Camera diagnostic (stethoscope) was missing from the pop-out camera window (#1395, reported by @Tschipel)** — The #1395 camera-diagnostic follow-up — stethoscope icon in the control bar, **Diagnose** button in the stream-error state, `CameraDiagnoseModal` — shipped wired into `EmbeddedCameraViewer.tsx` only, the *embedded* camera mode. It was never added to `CameraPage.tsx`, the standalone window that opens at `/camera/{id}` when `camera_view_mode` is `window` (the default). The reporter's support bundle had `"camera_view_mode": "window"`, so they were on `CameraPage` the whole time and genuinely could not see the stethoscope no matter how many container rebuilds or cache clears they tried — the JS bundle did contain the `camera.diagnose` strings (they come from `EmbeddedCameraViewer`), but that component never renders in window mode. Switching to overlay mode made it appear instantly, exactly as the reporter found. **Fix**: ported the diagnostic into `CameraPage.tsx` — the `Stethoscope` control-bar button (between **Refresh** and **Fullscreen**, matching the embedded viewer), a **Diagnose** button next to **Retry** in the `streamError` block, and the `CameraDiagnoseModal` render. No new i18n keys — `camera.diagnose.*` already exist in all 9 locales. The backend per-model camera-profile fix from the same issue is view-mode-agnostic and already applied; this only makes the diagnostic reachable in the default window mode. Frontend build clean.
- **A backend restart mid-print no longer duplicates the job in the archive (#1485, reported by @pwostran)** — When the server running Bambuddy restarted during an active print, the running job was duplicated in the archive — and deleting the duplicate didn't help: every subsequent restart while the print was still running spawned a fresh one. Both support bundles confirmed it: `WARNING Found stale 'printing' archive 3 (age: 9:46:23), marking as cancelled and creating new archive` → `Created archive 4`. On reconnect `on_print_start` fires (Bambuddy sees the printer running) and tries to re-attach to the existing archive in `main.py`. The reliable match is by `subtask_id`; the fallback is a name match plus — and this was the bug — a **4-hour staleness heuristic**: a name-matched `printing` archive older than 4h was assumed dead, marked `cancelled`, and a new archive created. Bambu prints routinely run far longer than 4h, so a genuine long print's *live* archive was destroyed and duplicated on every restart. **Two root causes, both fixed.** **(1) Queue/scheduled archives never persisted a restart-stable `subtask_id`.** Bambuddy mints a per-job id (`project_id`/`subtask_id`/`task_id`) inside `start_print` when it sends the `project_file` command, and the printer echoes it back — but often not within the ~10s before `on_print_start` first fires, so the expected-print branch's `if subtask_id and not archive.subtask_id` write got an empty value and the archive was left with no id. A later restart then had nothing to match on and fell through to the fragile name path. Fix: `BambuMQTTClient.start_print` now records the minted id on `last_dispatch_subtask_id`, and `on_print_start` falls back to it when the printer hasn't echoed `subtask_id` yet — so every dispatched archive persists a stable id and a restart resumes it by id, age-independent. **(2) The 4-hour cutoff itself.** Replaced with a progress-aware check: when a name-matched `printing` archive is found on restart, the printer's *current* reported progress decides resume-vs-stale, not wall-clock age. Real progress (or unknown progress — printer offline) always resumes the existing archive. It is only treated as a stale leftover when the printer clearly shows a *different, freshly-started* print — under 1% progress on an archive more than 2h old, a state a real in-progress print is never in. The arbitrary 4h constant is gone. **Net effect**: a restart mid-print resumes the existing archive (`started_at`, energy, timelapse intact) instead of ever cancelling it and creating a duplicate. **Tests**: 2 new in `test_bambu_mqtt.py` (`start_print` records `last_dispatch_subtask_id`, and updates it per submission); new `TestStaleVsResume` in `test_subtask_archive_resume.py` — 6 cases pinning the progress-aware decision (long print mid-run resumes; barely-started long print resumes; ~0% + old archive is stale; ~0% + young archive resumes; unknown progress never cancels; the sub-1%/2h boundary). 472 print-start / MQTT / scheduler / dispatch tests green; backend ruff clean.
- **File Manager no longer polls the printer over FTPS every 30 seconds while open (#1480, reported by @OscarsWorldTech)** — The reporter's P1S churned through MQTT disconnect/reconnect cycles and timelapse downloads silently failed. The support bundle showed the real picture: during the churn windows, MQTT (`Connection stale - no message for 60.2s`), FTPS (`_ssl.c:1015: The handshake operation timed out`) and the camera all timed out *together* and recovered together — the P1S's embedded controller saturating, not a network fault (wifi -44 dBm, Docker host networking). A visible contributor on Bambuddy's side: `FileManagerModal.tsx` ran its `getPrinterFiles` query with `refetchInterval: 30000`, so every 30 s while the File Manager modal sat open it opened a *fresh* FTPS connection — full TLS handshake — to re-list the current directory. A printer's file list doesn't change on its own; it only changes on upload / delete (the modal's mutations already `invalidateQueries`) or when a print finishes. The blind 30 s poll was pure load, and on a fragile controller like the P1S it was enough to tip MQTT and FTP into the timeouts above. **Fix**: the `refetchInterval` is removed. The listing still refreshes on modal open, on directory / tab change (the path is in the query key), after every upload / delete, and via the existing manual Refresh button — so nothing stops updating, the printer just isn't hammered. Reduces steady-state FTPS connection load while the modal is open from one handshake every 30 s to zero. 19 FileManagerModal tests green; frontend build clean.
+35 -10
View File
@@ -276,20 +276,35 @@ def _summarize_ffmpeg_stderr(text: str | None) -> str:
async def _read_ffmpeg_stderr(process: asyncio.subprocess.Process) -> str | None:
"""Read ffmpeg stderr for diagnostics (best-effort, non-blocking).
"""Read whatever ffmpeg has written to stderr so far (best-effort).
Returns the stderr content with ffmpeg's boilerplate banner stripped,
so log output stays focused on the actual error.
ffmpeg's stderr must be drained *incrementally*. A stalled-but-still-alive
ffmpeg — the typical P2S RTSP failure, where it connects but never produces
a frame — never closes stderr, so a plain ``stderr.read()`` (read-to-EOF)
blocks until the wait_for timeout and returns nothing, discarding the
banner + stream-analysis lines ffmpeg already printed. Reading in bounded
chunks returns the buffered output promptly whether or not ffmpeg has
exited. Returns the content with ffmpeg's boilerplate banner stripped.
"""
if not process or not process.stderr:
return None
chunks: list[bytes] = []
total = 0
cap = 65536
try:
data = await asyncio.wait_for(process.stderr.read(), timeout=2.0)
if not data:
return None
return _summarize_ffmpeg_stderr(data.decode(errors="replace")) or None
except (TimeoutError, Exception):
while total < cap:
chunk = await asyncio.wait_for(process.stderr.read(8192), timeout=2.0)
if not chunk:
break # EOF — ffmpeg has exited
chunks.append(chunk)
total += len(chunk)
except Exception:
# Timed out waiting for more data — ffmpeg is alive but quiet now.
# Fall through and return whatever it already printed.
pass
if not chunks:
return None
return _summarize_ffmpeg_stderr(b"".join(chunks).decode(errors="replace")) or None
async def generate_rtsp_mjpeg_stream(
@@ -365,9 +380,19 @@ async def generate_rtsp_mjpeg_stream(
_disconnect_events[stream_id] = disconnect_event
logger.info(
"Starting RTSP camera stream for %s (stream_id=%s, model=%s, fps=%s)", ip_address, stream_id, model, fps
"Starting RTSP camera stream for %s (stream_id=%s, model=%s, fps=%s, probesize=%s, analyzeduration=%s)",
ip_address,
stream_id,
model,
fps,
profile.probesize,
profile.analyzeduration,
)
logger.debug("ffmpeg command: %s ... (url hidden)", ffmpeg)
# Log the full argv so a support bundle shows the actual ffmpeg flags
# (probesize, analyzeduration, transport, ...). Only camera_url carries a
# secret (the access code), so redact just that one element.
_redacted_cmd = ["rtsp://<redacted>/streaming/live/1" if a == camera_url else a for a in cmd]
logger.debug("ffmpeg command: %s", " ".join(_redacted_cmd))
# On Windows, spawn ffmpeg in its own process group so that
# terminate() doesn't broadcast CTRL_C_EVENT to uvicorn (#605).
@@ -7,7 +7,9 @@ single click produced 555 lines across 30 retries. The helper strips the
banner so logs stay focused on the real error.
"""
from backend.app.api.routes.camera import _summarize_ffmpeg_stderr
import asyncio
from backend.app.api.routes.camera import _read_ffmpeg_stderr, _summarize_ffmpeg_stderr
_FAKE_BANNER = """ffmpeg version 7.1.3-0+deb13u1 Copyright (c) 2000-2025 the FFmpeg developers
built with gcc 14 (Debian 14.2.0-19)
@@ -66,3 +68,55 @@ def test_drops_blank_lines():
def test_banner_only_returns_empty():
"""If ffmpeg prints only the banner (no errors), the summary should be empty."""
assert _summarize_ffmpeg_stderr(_FAKE_BANNER) == ""
# --- _read_ffmpeg_stderr (#1395) -------------------------------------------
# A stalled-but-alive ffmpeg (the P2S RTSP failure) never closes stderr, so a
# read-to-EOF discarded everything it had already printed. _read_ffmpeg_stderr
# now drains incrementally and must return that buffered output.
class _FakeProcess:
"""Minimal stand-in for asyncio.subprocess.Process — only .stderr is read."""
def __init__(self, stderr):
self.stderr = stderr
def _reader_with(data: bytes, *, eof: bool) -> asyncio.StreamReader:
reader = asyncio.StreamReader()
if data:
reader.feed_data(data)
if eof:
reader.feed_eof()
return reader
async def test_read_stderr_captures_output_from_a_running_ffmpeg():
"""The #1395 regression: ffmpeg is alive and has NOT closed stderr (no EOF).
The output it already printed must still be returned, not discarded while
waiting for an EOF that never arrives."""
stderr = _FAKE_BANNER + "[rtsp @ 0x5] Could not find codec parameters\n"
proc = _FakeProcess(_reader_with(stderr.encode(), eof=False))
result = await _read_ffmpeg_stderr(proc)
assert result is not None
assert "Could not find codec parameters" in result
assert "ffmpeg version" not in result # banner still stripped
async def test_read_stderr_captures_output_from_an_exited_ffmpeg():
stderr = _FAKE_BANNER + "Error opening input: Connection refused\n"
proc = _FakeProcess(_reader_with(stderr.encode(), eof=True))
result = await _read_ffmpeg_stderr(proc)
assert result is not None
assert "Connection refused" in result
async def test_read_stderr_returns_none_when_no_stderr_pipe():
assert await _read_ffmpeg_stderr(_FakeProcess(None)) is None
async def test_read_stderr_returns_none_for_banner_only_output():
"""Banner with no actionable lines summarizes to empty -> None."""
proc = _FakeProcess(_reader_with(_FAKE_BANNER.encode(), eof=True))
assert await _read_ffmpeg_stderr(proc) is None