Merge pull request #2722 from bitbarista/fix/timelapse-orphaned-session-cleanup

fix(camera): sweep orphaned timelapse session directories on startup

backend/app/main.py

@@ -6844,6 +6844,18 @@ async def lifespan(app: FastAPI):
     # Start camera stream orphan cleanup
     start_camera_cleanup()
 
+    # One-shot sweep for timelapse session directories orphaned by a crash
+    # or restart that happened mid-print (in-memory session tracking can't
+    # survive that, and nothing else reaps the leftover frames/output file)
+    try:
+        from backend.app.services.layer_timelapse import cleanup_orphaned_timelapse_sessions
+
+        removed = cleanup_orphaned_timelapse_sessions()
+        if removed:
+            logging.getLogger(__name__).info("Removed %d orphaned timelapse session artifact(s)", removed)
+    except Exception as e:
+        logging.getLogger(__name__).warning("Orphaned timelapse session cleanup failed: %s", e)
+
     # Start expected-print TTL eviction (prevents memory leak when prints are
     # registered but on_print_start never fires)
     start_expected_prints_cleanup()

backend/app/services/layer_timelapse.py

@@ -6,6 +6,7 @@ Captures a frame on each layer change and stitches them into a video on print co
 import asyncio
 import logging
 import shutil
+import time
 from dataclasses import dataclass, field
 from datetime import datetime
 from pathlib import Path
@@ -18,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."""
@@ -273,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:
@@ -286,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):
@@ -303,3 +321,92 @@ def cancel_session(printer_id: int):
 def get_active_sessions() -> dict[int, TimelapseSession]:
     """Get all active timelapse sessions."""
     return _active_sessions.copy()
+
+
+def cleanup_orphaned_timelapse_sessions(min_age_seconds: float = 300) -> int:
+    """Remove timelapse_frames/<printer_id>/* left behind by a crash or
+    restart that happened while a session was active.
+
+    _active_sessions is in-memory only, so a process restart loses track of
+    any in-flight session without ever calling cancel_session()/cleanup() -
+    the frames directory (and, if stitching had already produced output
+    before the restart, a stray `timelapse_<session_id>.mp4`) are then
+    orphaned on disk with nothing else to reap them (unlike the ffmpeg
+    orphan janitor in routes/camera.py, there was no equivalent here).
+
+    Safe to call once at startup: normal operation always cleans up via
+    on_print_complete/cancel_session, so anything found here predates this
+    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.
+
+    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.
+    """
+    base_dir = settings.base_dir / "timelapse_frames"
+    if not base_dir.exists():
+        return 0
+
+    now = time.time()
+    removed = 0
+    for printer_dir in base_dir.iterdir():
+        if not printer_dir.is_dir():
+            continue
+        try:
+            printer_id = int(printer_dir.name)
+        except ValueError:
+            continue
+
+        active_session = _active_sessions.get(printer_id)
+        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 "<session_id>/"; stitched-but-not-yet-
+            # attached output files are "timelapse_<session_id>.mp4" (see
+            # 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:
+                    continue
+            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)
+                else:
+                    entry.unlink(missing_ok=True)
+                removed += 1
+                logger.info("Removed orphaned timelapse artifact: %s", entry)
+            except OSError as e:
+                logger.warning("Failed to remove orphaned timelapse artifact %s: %s", entry, e)
+
+    return removed

backend/tests/unit/services/test_layer_timelapse.py

@@ -4,6 +4,7 @@ Tests for the layer timelapse service.
 These tests cover session management and pure logic functions.
 """
 
+import time
 from datetime import datetime
 from pathlib import Path
 from unittest.mock import AsyncMock, MagicMock, patch
@@ -318,3 +319,235 @@ class TestGetActiveSessions:
                 assert 1 in _active_sessions
 
                 cancel_session(1)
+
+
+class TestCleanupOrphanedTimelapseSessions:
+    """_active_sessions is in-memory only, so a process restart mid-print
+    loses track of an active session without ever cleaning up its frames
+    directory (or a stitched-but-not-attached output .mp4). Confirmed live:
+    38MB of exactly this leftover on Carl's OrangePi after several restarts
+    during testing. cleanup_orphaned_timelapse_sessions() sweeps for it."""
+
+    def _touch_old(self, path, age_seconds=600):
+        import os
+
+        path.touch()
+        old = time.time() - age_seconds
+        os.utime(path, (old, old))
+
+    def _mkdir_old(self, path, age_seconds=600):
+        import os
+
+        path.mkdir(parents=True)
+        old = time.time() - age_seconds
+        os.utime(path, (old, old))
+
+    def test_removes_orphaned_frame_dir_and_stray_output(self, tmp_path):
+        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")
+        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 == 2
+        assert not (printer_dir / "20260101_000000").exists()
+        assert not (printer_dir / "timelapse_20260101_000000.mp4").exists()
+
+    def test_spares_the_currently_active_session(self, tmp_path):
+        from backend.app.services.layer_timelapse import (
+            TimelapseSession,
+            _active_sessions,
+            cleanup_orphaned_timelapse_sessions,
+        )
+
+        _active_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")
+            _active_sessions[1] = session
+            import os
+
+            old = time.time() - 600
+            os.utime(session.frames_dir, (old, old))
+
+            removed = cleanup_orphaned_timelapse_sessions(min_age_seconds=300)
+
+        assert removed == 0
+        assert session.frames_dir.exists()
+        _active_sessions.clear()
+
+    def test_spares_recently_modified_entries(self, tmp_path):
+        """Defensive margin: something modified within min_age_seconds is
+        left alone even if it doesn't match an active session, in case this
+        is ever invoked while a session is mid-creation."""
+        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)
+        (printer_dir / "20260101_000000").mkdir()
+
+        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 == 0
+        assert (printer_dir / "20260101_000000").exists()
+
+    def test_no_base_dir_is_a_no_op(self, tmp_path):
+        from backend.app.services.layer_timelapse import cleanup_orphaned_timelapse_sessions
+
+        with patch("backend.app.services.layer_timelapse.settings") as mock_settings:
+            mock_settings.base_dir = tmp_path / "does-not-exist"
+            removed = cleanup_orphaned_timelapse_sessions()
+
+        assert removed == 0
+
+    def test_ignores_non_numeric_printer_dirs(self, tmp_path):
+        """Defensive: unrelated directories under timelapse_frames/ (there
+        shouldn't be any, but printer_id is parsed from the dir name) must
+        not raise."""
+        from backend.app.services.layer_timelapse import (
+            _active_sessions,
+            cleanup_orphaned_timelapse_sessions,
+        )
+
+        _active_sessions.clear()
+        (tmp_path / "timelapse_frames" / "not-a-printer-id").mkdir(parents=True)
+
+        with patch("backend.app.services.layer_timelapse.settings") as mock_settings:
+            mock_settings.base_dir = tmp_path
+            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_<id>.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()