Procházet zdrojové kódy

fix(notifications): capture the snapshot outside the DB session (#2572)

The progress-milestone and HMS-error notification paths in
on_printer_status_change held a session across the ~15s camera snapshot
taken for the notification image, pinning a pooled connection per
milestone/error per printer.

The snapshot needs no DB: read the printer in a short session, release
it, grab the snapshot with none held, then open a fresh session for the
notification send (and lift the db-free MQTT publish out too). Pinned by
a test that fails if the snapshot runs while a session is open.
maziggy před 1 měsícem
rodič
revize
a5176349dd

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.5b2] - Unreleased
 ## [1.2.5b2] - Unreleased
 
 
 ### Fixed
 ### Fixed
+- **Progress-milestone and HMS-error notifications held a DB connection across the camera snapshot (#2572, reporter @Jostxxl)** — Both notification paths inside `on_printer_status_change` (the 25/50/75% milestone push and the new-HMS-error push) opened a database session, then captured a camera snapshot for the notification image — an up-to-15s RTSP grab — and sent the notification, all with the session held. So a pooled connection sat idle for the whole grab, per milestone/error, per printer; on a farm those fire constantly. The snapshot needs no database, so it now runs between two short sessions: one to read the printer name, then the grab with no connection held, then a fresh session for the notification send. Behaviour is unchanged; pinned by a test that fails if the snapshot ever runs while a session is open. The AMS-change notification path was left as-is for now (it holds a per-printer lock across its write and needs separate care). Continues the #2572 effort (camera stream, timelapse scan, finish photo).
 - **Finish-photo capture held a DB connection open across the whole camera grab (#2572, reporter @Jostxxl)** — When a print finishes, the background finish-photo task reads a couple of rows (the capture setting, the printer, the archive) and then runs a capture pipeline that can take tens of seconds — timelapse last-frame extraction, waiting up to 20s for the stage-22 producer, an external-camera HTTP grab, or a fresh RTSP shot. It held one database session open across that entire pipeline, so a pooled connection sat `idle in transaction` for the full capture, once per finishing print — and finishes cluster on a farm. It now reads what it needs in a short session, releases the connection, runs the capture with no session held, and re-opens a fresh short session only to append the photo to the archive. Behaviour is unchanged. Continues the #2572 effort (camera stream, timelapse scan) to stop holding sessions across slow I/O.
 - **Finish-photo capture held a DB connection open across the whole camera grab (#2572, reporter @Jostxxl)** — When a print finishes, the background finish-photo task reads a couple of rows (the capture setting, the printer, the archive) and then runs a capture pipeline that can take tens of seconds — timelapse last-frame extraction, waiting up to 20s for the stage-22 producer, an external-camera HTTP grab, or a fresh RTSP shot. It held one database session open across that entire pipeline, so a pooled connection sat `idle in transaction` for the full capture, once per finishing print — and finishes cluster on a farm. It now reads what it needs in a short session, releases the connection, runs the capture with no session held, and re-opens a fresh short session only to append the photo to the archive. Behaviour is unchanged. Continues the #2572 effort (camera stream, timelapse scan) to stop holding sessions across slow I/O.
 - **Timelapse scan held a DB connection open across every FTP round-trip (#2572, reporter @Jostxxl)** — After a print completes, `_scan_for_timelapse_with_retries` polls the printer's FTP server for the new timelapse file (up to 4 retry attempts, plus a name-match fallback). Each attempt opened one database session and held it across the FTP directory listing *and* the multi-MB video download — so a pooled connection sat `idle in transaction` for the whole transfer, once per attempt, per completed print. When several prints finish together on a farm that adds up. The scan now reads the archive + printer in a short session, releases the connection, does the FTP list/download with no session held, and re-opens a fresh short session only to attach the downloaded file. Behaviour is unchanged; the existing scan tests already exercise the read→download→attach path. Continues the #2572 effort (after the camera-stream fix) to stop holding sessions across slow I/O; the scheduler paths were reviewed and found already bounded (single loop + capped concurrent uploads, with an explicit pre-dispatch commit) so they were left as-is.
 - **Timelapse scan held a DB connection open across every FTP round-trip (#2572, reporter @Jostxxl)** — After a print completes, `_scan_for_timelapse_with_retries` polls the printer's FTP server for the new timelapse file (up to 4 retry attempts, plus a name-match fallback). Each attempt opened one database session and held it across the FTP directory listing *and* the multi-MB video download — so a pooled connection sat `idle in transaction` for the whole transfer, once per attempt, per completed print. When several prints finish together on a farm that adds up. The scan now reads the archive + printer in a short session, releases the connection, does the FTP list/download with no session held, and re-opens a fresh short session only to attach the downloaded file. Behaviour is unchanged; the existing scan tests already exercise the read→download→attach path. Continues the #2572 effort (after the camera-stream fix) to stop holding sessions across slow I/O; the scheduler paths were reviewed and found already bounded (single loop + capped concurrent uploads, with an explicit pre-dispatch commit) so they were left as-is.
 - **Live camera stream held a database connection open for its entire duration (#2572, reporter @Jostxxl)** — The `/camera/stream` MJPEG endpoint took its printer row via `Depends(get_db)`, but `get_db` is a `yield` dependency: its session isn't released until the response body finishes streaming, which for a live stream is however long the browser tab stays open — minutes to hours. On a large farm every open camera tile therefore pinned one pooled DB connection `idle in transaction`, so a wall of dashboards could drain the pool on its own (a top contributor to the exhaustion in #2572). The endpoint now fetches the printer in a short-lived session and releases the connection *before* it starts streaming (`expire_on_commit=False` keeps the already-loaded columns readable). Pinned by a regression test that fails if a `get_db`-held session is ever re-added to the route. Part of the broader effort to stop holding sessions across slow MQTT/FTP/camera/3MF work.
 - **Live camera stream held a database connection open for its entire duration (#2572, reporter @Jostxxl)** — The `/camera/stream` MJPEG endpoint took its printer row via `Depends(get_db)`, but `get_db` is a `yield` dependency: its session isn't released until the response body finishes streaming, which for a live stream is however long the browser tab stays open — minutes to hours. On a large farm every open camera tile therefore pinned one pooled DB connection `idle in transaction`, so a wall of dashboards could drain the pool on its own (a top contributor to the exhaustion in #2572). The endpoint now fetches the printer in a short-lived session and releases the connection *before* it starts streaming (`expire_on_commit=False` keeps the already-loaded columns readable). Pinned by a regression test that fails if a `get_db`-held session is ever re-added to the route. Part of the broader effort to stop holding sessions across slow MQTT/FTP/camera/3MF work.

+ 52 - 43
backend/app/main.py

@@ -1236,21 +1236,25 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
         if current_milestone > last_milestone:
         if current_milestone > last_milestone:
             _last_progress_milestone[printer_id] = current_milestone
             _last_progress_milestone[printer_id] = current_milestone
             try:
             try:
-                async with async_session() as db:
-                    from backend.app.models.printer import Printer
+                from backend.app.models.printer import Printer
 
 
+                # Read the printer in a short session and release the connection
+                # BEFORE the ~15s camera snapshot below — holding it across the grab
+                # pinned a pooled connection per milestone, per printer (issue #2572).
+                async with async_session() as db:
                     result = await db.execute(select(Printer).where(Printer.id == printer_id))
                     result = await db.execute(select(Printer).where(Printer.id == printer_id))
                     printer = result.scalar_one_or_none()
                     printer = result.scalar_one_or_none()
-                    printer_name = printer.name if printer else f"Printer {printer_id}"
-                    filename = state.subtask_name or state.gcode_file or "Unknown"
-                    # remaining_time is in minutes, convert to seconds for notification
-                    remaining_time_seconds = state.remaining_time * 60 if state.remaining_time else None
 
 
-                    # Capture camera snapshot for notification image attachment
-                    image_data = await _capture_snapshot_for_notification(
-                        printer_id, printer, logging.getLogger(__name__)
-                    )
+                printer_name = printer.name if printer else f"Printer {printer_id}"
+                filename = state.subtask_name or state.gcode_file or "Unknown"
+                # remaining_time is in minutes, convert to seconds for notification
+                remaining_time_seconds = state.remaining_time * 60 if state.remaining_time else None
 
 
+                # Capture camera snapshot for notification image attachment (no DB held).
+                image_data = await _capture_snapshot_for_notification(printer_id, printer, logging.getLogger(__name__))
+
+                # Notification send needs a session (provider/template lookups).
+                async with async_session() as db:
                     await notification_service.on_print_progress(
                     await notification_service.on_print_progress(
                         printer_id,
                         printer_id,
                         printer_name,
                         printer_name,
@@ -1293,30 +1297,35 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
             new_errors = [e for e in current_hms_errors if f"{e.attr:08x}" in new_error_codes and e.severity >= 2]
             new_errors = [e for e in current_hms_errors if f"{e.attr:08x}" in new_error_codes and e.severity >= 2]
 
 
             try:
             try:
-                async with async_session() as db:
-                    from backend.app.models.printer import Printer
+                from backend.app.models.printer import Printer
 
 
+                # Read the printer in a short session and release the connection
+                # BEFORE the ~15s camera snapshot below (issue #2572).
+                async with async_session() as db:
                     result = await db.execute(select(Printer).where(Printer.id == printer_id))
                     result = await db.execute(select(Printer).where(Printer.id == printer_id))
                     printer = result.scalar_one_or_none()
                     printer = result.scalar_one_or_none()
-                    printer_name = printer.name if printer else f"Printer {printer_id}"
-
-                    # Format error details for notification
-                    # Module 0x07 = AMS/Filament, 0x05 = Nozzle, 0x0C = Motion Controller, etc.
-                    module_names = {
-                        0x03: "Print/Task",
-                        0x05: "Nozzle/Extruder",
-                        0x07: "AMS/Filament",
-                        0x0C: "Motion Controller",
-                        0x12: "Chamber",
-                    }
 
 
-                    from backend.app.services.hms_errors import get_error_description
+                printer_name = printer.name if printer else f"Printer {printer_id}"
 
 
-                    # Capture camera snapshot once for all error notifications
-                    error_image_data = await _capture_snapshot_for_notification(
-                        printer_id, printer, logging.getLogger(__name__)
-                    )
+                # Format error details for notification
+                # Module 0x07 = AMS/Filament, 0x05 = Nozzle, 0x0C = Motion Controller, etc.
+                module_names = {
+                    0x03: "Print/Task",
+                    0x05: "Nozzle/Extruder",
+                    0x07: "AMS/Filament",
+                    0x0C: "Motion Controller",
+                    0x12: "Chamber",
+                }
 
 
+                from backend.app.services.hms_errors import get_error_description
+
+                # Capture camera snapshot once for all error notifications (no DB held).
+                error_image_data = await _capture_snapshot_for_notification(
+                    printer_id, printer, logging.getLogger(__name__)
+                )
+
+                # Notification sends need a session (provider/template lookups).
+                async with async_session() as db:
                     sent_count = 0
                     sent_count = 0
                     for error in new_errors:
                     for error in new_errors:
                         module_name = module_names.get(error.module, f"Module 0x{error.module:02X}")
                         module_name = module_names.get(error.module, f"Module 0x{error.module:02X}")
@@ -1345,21 +1354,21 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
                             f"[HMS] Sent notification for {sent_count} error(s) on printer {printer_id}"
                             f"[HMS] Sent notification for {sent_count} error(s) on printer {printer_id}"
                         )
                         )
 
 
-                    # Also publish to MQTT relay
-                    printer_info = printer_manager.get_printer(printer_id)
-                    if printer_info:
-                        errors_data = [
-                            {
-                                "code": e.code,
-                                "attr": e.attr,
-                                "module": e.module,
-                                "severity": e.severity,
-                            }
-                            for e in new_errors
-                        ]
-                        await mqtt_relay.on_printer_error(
-                            printer_id, printer_info.name, printer_info.serial_number, errors_data
-                        )
+                # Also publish to MQTT relay (no DB).
+                printer_info = printer_manager.get_printer(printer_id)
+                if printer_info:
+                    errors_data = [
+                        {
+                            "code": e.code,
+                            "attr": e.attr,
+                            "module": e.module,
+                            "severity": e.severity,
+                        }
+                        for e in new_errors
+                    ]
+                    await mqtt_relay.on_printer_error(
+                        printer_id, printer_info.name, printer_info.serial_number, errors_data
+                    )
 
 
             except Exception as e:
             except Exception as e:
                 logging.getLogger(__name__).warning(f"HMS error notification failed: {e}")
                 logging.getLogger(__name__).warning(f"HMS error notification failed: {e}")

+ 78 - 0
backend/tests/unit/test_printer_offline_notification.py

@@ -256,3 +256,81 @@ class TestOfflineEdgeDetection:
         assert first_task is second_task
         assert first_task is second_task
         if first_task is not None:
         if first_task is not None:
             first_task.cancel()
             first_task.cancel()
+
+
+class TestProgressMilestoneSessionHygiene:
+    """The progress-milestone notification path must capture the camera
+    snapshot WITHOUT holding a DB session (issue #2572): a ~15s RTSP grab
+    across an open session pinned a pooled connection per milestone, per
+    printer. The read (printer name) and the send (provider lookups) each get
+    their own short session; the snapshot happens in between with none held."""
+
+    @staticmethod
+    def _printing_state(progress: int):
+        st = _state(connected=True, state="RUNNING")
+        st.progress = progress
+        st.remaining_time = 30
+        st.gcode_file = "benchy.gcode"
+        return st
+
+    @pytest.mark.asyncio
+    async def test_milestone_captures_snapshot_outside_session_and_notifies(self):
+        main_module._last_progress_milestone.clear()
+
+        printer = SimpleNamespace(id=1, name="Workshop")
+        db = AsyncMock()
+        db.execute = AsyncMock(return_value=MagicMock(scalar_one_or_none=MagicMock(return_value=printer)))
+
+        # Stateful session that tracks how many sessions are currently open.
+        open_sessions = {"count": 0}
+
+        class _SessionCM:
+            async def __aenter__(self):
+                open_sessions["count"] += 1
+                return db
+
+            async def __aexit__(self, *exc):
+                open_sessions["count"] -= 1
+                return False
+
+        snap_calls = []
+
+        async def _snap(printer_id, prn, _logger):
+            # The whole point of the fix (#2572): the ~15s camera grab must NOT
+            # run while a DB session is held. On the old code the snapshot sat
+            # inside the milestone session, so this would be 1.
+            assert open_sessions["count"] == 0, "camera snapshot ran while a DB session was held"
+            snap_calls.append((printer_id, prn))
+            return b"jpeg-bytes"
+
+        ws_mgr = MagicMock()
+        ws_mgr.send_printer_status = AsyncMock()
+        relay = MagicMock()
+        relay.on_printer_status = AsyncMock()
+        pm = MagicMock()
+        pm.get_printer.return_value = None
+        pm.get_model.return_value = ""
+
+        with (
+            patch("backend.app.main.ws_manager", ws_mgr),
+            patch("backend.app.main.mqtt_relay", relay),
+            patch("backend.app.main.printer_manager", pm),
+            patch("backend.app.main.spawn_background_task"),
+            patch("backend.app.main.printer_state_to_dict", return_value={}),
+            patch("backend.app.main.async_session", side_effect=lambda: _SessionCM()),
+            patch("backend.app.main._capture_snapshot_for_notification", new=_snap),
+            patch("backend.app.main.notification_service") as mock_notif,
+        ):
+            mock_notif.on_print_progress = AsyncMock()
+
+            await main_module.on_printer_status_change(1, self._printing_state(25))
+
+            # Snapshot ran (with the detached printer) and outside any session.
+            assert snap_calls == [(1, printer)]
+            # The notification fired carrying that image (send legitimately holds a session).
+            mock_notif.on_print_progress.assert_awaited_once()
+            assert mock_notif.on_print_progress.await_args.kwargs["image_data"] == b"jpeg-bytes"
+            # Every session opened was also closed — none leaked past the handler.
+            assert open_sessions["count"] == 0
+
+        main_module._last_progress_milestone.clear()