diff --git a/CHANGELOG.md b/CHANGELOG.md index 052c90434..8ce788bd6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -44,7 +44,7 @@ All notable changes to Bambuddy will be documented in this file. - **A long-running camera stream could eventually stall itself, with nothing in the log to explain it (#2707)** — ffmpeg's error output was only read when something had already gone wrong, which meant that for the entire life of a working stream nobody read it. ffmpeg writes a startup banner, its analysis of the incoming video, and then a progress line at a steady rate, and the operating system only buffers a fixed amount of that before it stops the writer. Once that happened ffmpeg would block trying to write the next line, stop producing frames, and the stream's own timeout would fire — reported as `RTSP read timeout` and a reconnect, with no indication that Bambuddy had starved it. How long it takes to reach that point is unmeasured and clearly long: one stream ran 21 minutes 36 seconds without trouble, so this is a limit that was being ignored rather than a fault anyone has reported. **Fix.** A streaming ffmpeg's error output is now read continuously and the most recent portion kept, so the limit cannot be reached. The kept portion is what gets logged when a stream does fail, which is more useful than before: it holds what ffmpeg said as things went wrong, where reading the buffer on demand returned whatever it had printed first — usually the startup banner, which is then discarded as noise. Credentials are masked on this path through the same single funnel as every other camera log. Covered by tests for continuous draining, the size bound, keeping the newest output, credential masking, and the ownership handover with the shutdown path — reading the same output from two places at once is an error, so only one owner reads it at a time. - **Reopening the camera quickly could leave the new stream invisible to Bambuddy (#2707)** — Closing a camera view and opening it again straight away could leave the newly started stream unregistered, even though it was running and showing frames. The consequences were all indirect, which is what made it hard to spot: Bambuddy believed no viewer was attached, so Obico polling and snapshots would open a second camera connection and fight the live view — precisely what the guards added in #1348 and #1271 exist to prevent; the background cleanup task saw a camera process with no stream attached to it and killed the live stream as an orphan, usually within a minute; and pressing Stop reported that it had stopped nothing while the view was still running. **Root cause.** Each printer's fan-out stream was registered under a key derived from the printer alone, so every successive stream for that printer reused the same key, and the departing stream's cleanup removed whatever was registered under it — including its own replacement. The same cleanup also cleared the printer's most recent camera frame unconditionally, discarding the new stream's frame. It needed the old and new streams to overlap, which the four-second teardown fixed above made easy to hit. **Fix.** Each stream now gets its own registry key, so one stream can only ever clean up after itself — the same approach the external-camera path already uses (#2675) — and the shared per-printer frame is only released when no stream for that printer is left running. Covered by tests for both halves, including one that drives the real cleanup path with a second stream already registered. - **Closing the camera held the printer's camera connection for four more seconds, then logged an error that wasn't true (#2707)** — 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. -- **A crash or restart mid-print left layer-timelapse files behind forever (#2709, reporter @bitbarista)** — `timelapse_frames/` grew slowly and never shrank on its own. After several routine restarts during testing, it had accumulated 38MB: three abandoned frame directories and two 48-byte `.mp4` files from stitches that never finished writing. **Root cause.** Which timelapse session is active lives only in memory. A restart for any reason — a redeploy, a crash, a power loss — loses that bookkeeping instantly, but the frames already written for that session, and any partially-stitched output file, stay on disk with nothing left that knows they exist. `on_print_complete`'s cleanup never runs for them, because nothing calls it: the session it would clean up no longer has an entry to be found by. A restart-recovered print doesn't get a replacement session either (`_maybe_start_layer_timelapse` only fires on a fresh `PRINT_START` event, #1353), so an orphaned directory can never be resumed or claimed by anything — it just sits there. **Fix.** A one-time sweep on startup removes any `timelapse_frames//` entry that doesn't match that printer's current session and is old enough not to be a startup race (five minutes). Verified against the real 38MB of leftovers: startup logged each of the five removed by name, and the directory dropped to 8KB. Covered by tests for the orphaned-directory and stray-output-file cases, sparing a genuinely active session, sparing anything too recent to be sure about, and two defensive cases (no `timelapse_frames/` directory yet, an unrelated non-numeric entry under it). +- **A crash or restart mid-print left layer-timelapse files behind forever (#2709, reporter @bitbarista)** — `timelapse_frames/` grew slowly and never shrank on its own. After several routine restarts during testing, it had accumulated 38MB: three abandoned frame directories and two 48-byte `.mp4` files from stitches that never finished writing. **Root cause.** Which timelapse session is active lives only in memory. A restart for any reason — a redeploy, a crash, a power loss — loses that bookkeeping instantly, but the frames already written for that session, and any partially-stitched output file, stay on disk with nothing left that knows they exist. `on_print_complete`'s cleanup never runs for them, because nothing calls it: the session it would clean up no longer has an entry to be found by. A restart-recovered print doesn't get a replacement session either (`_maybe_start_layer_timelapse` only fires on a fresh `PRINT_START` event, #1353), so an orphaned directory can never be resumed or claimed by anything — it just sits there. **Fix.** A one-time sweep on startup removes any `timelapse_frames//` entry that doesn't match a session that printer is currently recording or stitching, and that is old enough not to be a startup race (five minutes). Only this feature's own artifacts are swept — a frames directory or a `timelapse_.mp4` — so anything else that ends up under that folder is left alone rather than deleted for being old. Verified against the real 38MB of leftovers: startup logged each of the five removed by name, and the directory dropped to 8KB. Covered by tests for the orphaned-directory and stray-output-file cases, sparing a genuinely active session, sparing one that is mid-stitch (the window where the session has already been handed to ffmpeg and is no longer listed as active), sparing anything too recent to be sure about, leaving unrelated files alone, not counting a removal that failed as a success, and two defensive cases (no `timelapse_frames/` directory yet, an unrelated non-numeric entry under it). - **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. - **The same one-shot-capture collision could happen on external cameras too, with no viewer attached (#2707 follow-up, reporter @bitbarista)** — #2705 fixed simultaneous captures colliding on the built-in camera path, keyed by printer IP through `capture_camera_frame_bytes()`. External cameras reach the same kind of collision through a different function — `external_camera.capture_frame()` — that #2705 didn't touch, and a V4L2 USB device allows exactly one open handle just like Bambu's own RTSP limit. Nothing coalesced two one-shot capturers here either: Obico polling, the in-print frame bank, the finish-photo moment, plate detection and the notification snapshot could each open their own connection to the same USB camera and collide, with `is_stream_active()` unable to help since that guard only stops a capturer from competing with an *attached viewer*, not with another capturer. **Fix.** The same shape of fix as #2705, applied to `capture_frame()`: concurrent callers for the same camera (URL, type, and — since #1177's snapshot override routes to a different endpoint entirely — snapshot URL) share one capture rather than opening a second connection. Coalesces, does not cache, so a call after the previous one finishes always captures fresh. Each caller keeps its own timeout, giving up leaves the capture running for whoever else is waiting, and a capture that fails doesn't hand its failure to a caller that never got a turn of its own. One visible consequence, mirroring the label #2705 added to the built-in **Diagnose** tool: pressing **Test** on an external camera while a capture is already running now says the frame was shared with it, because the result is real but the test did not open a connection of its own — and forcing one would be the very second handle this change exists to prevent. Covered by tests mirroring #2705's: the reported-shape collision, five callers sharing one connection, per-camera and per-snapshot-URL 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 — plus, for this path specifically, that an unexpected error is reported as a failed capture rather than raised at every waiting caller at once, and that the shared-capture log lines redact credentials, since an RTSP camera URL routinely carries `user:pass@` where the built-in path's key is only an IP address. - **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. diff --git a/backend/app/services/layer_timelapse.py b/backend/app/services/layer_timelapse.py index 213757632..a48902c84 100644 --- a/backend/app/services/layer_timelapse.py +++ b/backend/app/services/layer_timelapse.py @@ -19,6 +19,15 @@ logger = logging.getLogger(__name__) # Active timelapse sessions: {printer_id: TimelapseSession} _active_sessions: dict[int, "TimelapseSession"] = {} +# Sessions whose frames are being stitched right now: {printer_id: session_id}. +# on_print_complete removes the session from _active_sessions *before* handing +# frames_dir to ffmpeg, so for the length of a stitch (up to 300s) nothing in +# _active_sessions marks that directory as in use. Without this second registry +# the only thing standing between an in-progress stitch and +# cleanup_orphaned_timelapse_sessions() is the age margin — whose default is +# exactly the stitch timeout, so there is no headroom at all. +_finalizing_sessions: dict[int, str] = {} + def get_ffmpeg_path() -> str | None: """Get the path to ffmpeg executable.""" @@ -274,6 +283,12 @@ async def on_print_complete(printer_id: int) -> Path | None: # Create output path in parent of frames dir output_path = session.frames_dir.parent / f"timelapse_{session.session_id}.mp4" + # The session is already out of _active_sessions, so mark it finalizing for + # the length of the stitch — otherwise a sweep running now sees a frames + # directory that matches no session and whose mtime is the last layer's + # write, which on a tall print's final layer is easily older than the age + # margin, and deletes ffmpeg's input from under it. + _finalizing_sessions[printer_id] = session.session_id try: success = await session.stitch(output_path) if success: @@ -287,6 +302,8 @@ async def on_print_complete(printer_id: int) -> Path | None: logger.error("Timelapse completion failed: %s", e) session.cleanup() return None + finally: + _finalizing_sessions.pop(printer_id, None) def cancel_session(printer_id: int): @@ -322,8 +339,21 @@ def cleanup_orphaned_timelapse_sessions(min_age_seconds: float = 300) -> int: process - and a restart-recovered print doesn't get a new timelapse session either (`_maybe_start_layer_timelapse` is only wired into fresh PRINT_START events, see #1353), so an orphaned directory can never be - resumed. `min_age_seconds` is just a defensive margin against reordering - if this is ever also called mid-run. + resumed. + + Also safe to call mid-run, which needs all three guards rather than the + age margin alone: + + * `_active_sessions` covers a session that is still capturing. + * `_finalizing_sessions` covers the stitch window. on_print_complete drops + the session from `_active_sessions` before handing frames_dir to ffmpeg, + so without this the directory matches no session for up to 300s while + being actively read. + * `min_age_seconds` covers the remaining gap - a session in the middle of + being created, and the stitched `.mp4` between ffmpeg finishing it and + the caller attaching and unlinking it. Both are freshly written, so the + margin has real headroom there; it did NOT have any for the stitch + window, whose length is bounded by the same 300s. Returns the number of orphaned directories/files removed. """ @@ -342,14 +372,24 @@ def cleanup_orphaned_timelapse_sessions(min_age_seconds: float = 300) -> int: continue active_session = _active_sessions.get(printer_id) - active_session_id = active_session.session_id if active_session else None + in_use_session_ids = { + active_session.session_id if active_session else None, + _finalizing_sessions.get(printer_id), + } - {None} for entry in printer_dir.iterdir(): # Frame dirs are named "/"; stitched-but-not-yet- # attached output files are "timelapse_.mp4" (see - # on_print_complete's output_path). - entry_session_id = entry.name.removeprefix("timelapse_").removesuffix(".mp4") if entry.is_file() else entry.name - if entry_session_id == active_session_id: + # on_print_complete's output_path). Anything else under here was + # not written by this module, so leave it alone rather than + # deleting a file on the strength of its age. + if entry.is_dir(): + entry_session_id = entry.name + elif entry.name.startswith("timelapse_") and entry.name.endswith(".mp4"): + entry_session_id = entry.name[len("timelapse_") : -len(".mp4")] + else: + continue + if entry_session_id in in_use_session_ids: continue try: if now - entry.stat().st_mtime < min_age_seconds: @@ -357,8 +397,11 @@ def cleanup_orphaned_timelapse_sessions(min_age_seconds: float = 300) -> int: except OSError: continue try: + # No ignore_errors: it would swallow a failed removal while the + # count and the log line below still claimed success, and that + # log is the only evidence an operator has of what was deleted. if entry.is_dir(): - shutil.rmtree(entry, ignore_errors=True) + shutil.rmtree(entry) else: entry.unlink(missing_ok=True) removed += 1 diff --git a/backend/tests/unit/services/test_layer_timelapse.py b/backend/tests/unit/services/test_layer_timelapse.py index 06102413c..8d3629567 100644 --- a/backend/tests/unit/services/test_layer_timelapse.py +++ b/backend/tests/unit/services/test_layer_timelapse.py @@ -369,7 +369,6 @@ class TestCleanupOrphanedTimelapseSessions: ) _active_sessions.clear() - printer_dir = tmp_path / "timelapse_frames" / "1" with patch("backend.app.services.layer_timelapse.settings") as mock_settings: mock_settings.base_dir = tmp_path @@ -433,3 +432,122 @@ class TestCleanupOrphanedTimelapseSessions: removed = cleanup_orphaned_timelapse_sessions() assert removed == 0 + + def test_spares_a_session_that_is_mid_stitch(self, tmp_path): + """on_print_complete drops the session from _active_sessions before it + hands frames_dir to ffmpeg, so for the length of a stitch (up to 300s) + the directory matches no active session. Its mtime is the last layer's + frame write, which on a tall print's final layer is easily older than + the age margin — and the margin's default IS the stitch timeout, so it + offers no headroom here. _finalizing_sessions covers that window.""" + import os + + from backend.app.services.layer_timelapse import ( + TimelapseSession, + _active_sessions, + _finalizing_sessions, + cleanup_orphaned_timelapse_sessions, + ) + + _active_sessions.clear() + _finalizing_sessions.clear() + + with patch("backend.app.services.layer_timelapse.settings") as mock_settings: + mock_settings.base_dir = tmp_path + session = TimelapseSession(1, 100, "/dev/video1", "usb") + (session.frames_dir / "layer_00001.jpg").write_bytes(b"x") + old = time.time() - 600 + os.utime(session.frames_dir, (old, old)) + + # Exactly the state on_print_complete is in while ffmpeg runs. + _active_sessions.pop(1, None) + _finalizing_sessions[1] = session.session_id + + removed = cleanup_orphaned_timelapse_sessions(min_age_seconds=300) + + assert removed == 0 + assert session.frames_dir.exists(), "ffmpeg's input was deleted mid-stitch" + _finalizing_sessions.clear() + + @pytest.mark.asyncio + async def test_on_print_complete_clears_the_finalizing_marker(self, tmp_path): + """Including when the stitch fails — a leaked marker would make the + sweep skip that printer's leftovers forever.""" + from backend.app.services.layer_timelapse import ( + TimelapseSession, + _active_sessions, + _finalizing_sessions, + on_print_complete, + ) + + _active_sessions.clear() + _finalizing_sessions.clear() + + with patch("backend.app.services.layer_timelapse.settings") as mock_settings: + mock_settings.base_dir = tmp_path + session = TimelapseSession(1, 100, "/dev/video1", "usb") + session.frame_count = 3 + _active_sessions[1] = session + + with patch.object(TimelapseSession, "stitch", AsyncMock(side_effect=RuntimeError("ffmpeg died"))): + result = await on_print_complete(1) + + assert result is None + assert 1 not in _finalizing_sessions + + def test_leaves_unrelated_files_alone(self, tmp_path): + """Only this module's own artifacts are swept. A file that is neither a + session directory nor timelapse_.mp4 was put there by something + else, and age is not a reason to delete it.""" + from backend.app.services.layer_timelapse import ( + _active_sessions, + cleanup_orphaned_timelapse_sessions, + ) + + _active_sessions.clear() + printer_dir = tmp_path / "timelapse_frames" / "1" + printer_dir.mkdir(parents=True) + stranger = printer_dir / "notes.txt" + self._touch_old(stranger) + self._touch_old(printer_dir / "timelapse_20260101_000000.mp4") + + with patch("backend.app.services.layer_timelapse.settings") as mock_settings: + mock_settings.base_dir = tmp_path + removed = cleanup_orphaned_timelapse_sessions(min_age_seconds=300) + + assert removed == 1 + assert stranger.exists() + assert not (printer_dir / "timelapse_20260101_000000.mp4").exists() + + def test_a_removal_that_fails_is_not_counted_as_removed(self, tmp_path): + """The count and the log line are the only evidence an operator has of + what was deleted, so a failed rmtree must not be reported as a success. + + The stub honours rmtree's real contract — ignore_errors=True swallows + the failure and returns normally — because that is the whole point: a + caller passing it gets a silent no-op that the surrounding + ``except OSError`` can never see, and would still count and log the + directory as removed. A stub that raised unconditionally would pass + either way and prove nothing. + """ + from backend.app.services.layer_timelapse import ( + _active_sessions, + cleanup_orphaned_timelapse_sessions, + ) + + _active_sessions.clear() + printer_dir = tmp_path / "timelapse_frames" / "1" + self._mkdir_old(printer_dir / "20260101_000000") + + def rmtree_on_read_only_fs(path, ignore_errors=False, **kwargs): + if ignore_errors: + return # silently does nothing, exactly like the real thing + raise OSError("read-only fs") + + with patch("backend.app.services.layer_timelapse.settings") as mock_settings: + mock_settings.base_dir = tmp_path + with patch("backend.app.services.layer_timelapse.shutil.rmtree", rmtree_on_read_only_fs): + removed = cleanup_orphaned_timelapse_sessions(min_age_seconds=300) + + assert removed == 0, "a directory that is still on disk was reported as removed" + assert (printer_dir / "20260101_000000").exists()