Browse Source

fix(finish-photo): release DB connection during the camera capture (#2572)

The background finish-photo task held one session open across the whole
capture pipeline (timelapse extraction, up to 20s stage-22 wait,
external-camera/RTSP grab) — tens of seconds of a pooled connection
idle-in-transaction per finishing print.

Read the setting/printer/archive in a short session, release it, run the
capture with no session held, then re-open a fresh short session only to
append the photo. Logic unchanged.
maziggy 1 month ago
parent
commit
c1d25af7f1
2 changed files with 142 additions and 133 deletions
  1. 1 0
      CHANGELOG.md
  2. 141 133
      backend/app/main.py

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.5b2] - Unreleased
 
 ### Fixed
+- **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.
 - **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.
 - **PostgreSQL connection-pool exhaustion on large printer farms (#2572, reporter @Jostxxl)** — On a ~93-printer farm the SQLAlchemy pool (hard-coded `pool_size=10` + `max_overflow=20` = 30 connections) was repeatedly saturated with all connections `idle in transaction`; unrelated API requests then waited out the 30-second pool timeout or failed in the auth middleware, and an unauthenticated `/api/v1/printers` probe took ~25s to return 401. Three things fed the pressure: the pool was fixed and not configurable; every authenticated request re-queried `auth_enabled` from the DB (the middleware alone opened a session per request just to probe it); and the pool was small for a farm. This change (a) makes pool sizing configurable via `DB_POOL_SIZE` / `DB_MAX_OVERFLOW` / `DB_POOL_TIMEOUT` / `DB_POOL_RECYCLE` env vars and raises the PostgreSQL default to `20` + `80` (100 total) with `pool_pre_ping` and a 1800s `pool_recycle`; (b) caches the `auth_enabled` probe for 30s — only the *enabled* result is ever cached, so a stale read can only ever fail closed (require auth), never open, and any toggle invalidates it immediately; and (c) adds a `GET /api/v1/system/db-pool` diagnostic exposing the resolved config plus live `checked_out` / `checked_in` / `overflow` gauges (read without checking out a connection, so it stays truthful under saturation). Note: connections being held across slow MQTT/FTP/camera/3MF work — the underlying reason transactions sit idle — is a deeper session-hygiene change tracked separately; this drop relieves and instruments the problem and makes the farm sizing configurable. See the PostgreSQL wiki page for large-farm tuning and the required `max_connections` headroom.

+ 141 - 133
backend/app/main.py

@@ -4873,152 +4873,160 @@ async def on_print_complete(printer_id: int, data: dict):
 
             from backend.app.api.routes.camera import _active_chamber_streams, _active_streams, get_buffered_frame
 
+            # Read phase: settings + printer + archive in a short session, released
+            # BEFORE the capture pipeline below. The capture (timelapse last-frame,
+            # stage-22 wait, external-camera grab, or a fresh RTSP shot) can take
+            # tens of seconds; holding this session across it pinned one pooled
+            # connection idle-in-transaction per finishing print (issue #2572).
             async with async_session() as db:
                 from backend.app.api.routes.settings import get_setting
+                from backend.app.models.archive import PrintArchive
+                from backend.app.models.printer import Printer
 
                 capture_enabled = await get_setting(db, "capture_finish_photo")
+                if capture_enabled is not None and capture_enabled.lower() != "true":
+                    return None
+                if not archive_id:
+                    return None
 
-                if capture_enabled is None or capture_enabled.lower() == "true":
-                    from backend.app.models.printer import Printer
+                printer = (await db.execute(select(Printer).where(Printer.id == printer_id))).scalar_one_or_none()
+                archive = (
+                    await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
+                ).scalar_one_or_none()
 
-                    result = await db.execute(select(Printer).where(Printer.id == printer_id))
-                    printer = result.scalar_one_or_none()
-
-                    if printer and archive_id:
-                        from backend.app.models.archive import PrintArchive
-
-                        result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
-                        archive = result.scalar_one_or_none()
+            if not printer or not archive:
+                return None
 
-                        if archive:
-                            import uuid
-                            from datetime import datetime
-                            from pathlib import Path
+            import uuid
+            from datetime import datetime
+            from pathlib import Path
 
-                            if archive.file_path:
-                                archive_dir = app_settings.base_dir / Path(archive.file_path).parent
-                            else:
-                                logger.warning("[PHOTO-BG] Archive %s has no file_path, using fallback dir", archive_id)
-                                archive_dir = app_settings.archive_dir / str(archive.id)
-                            photo_filename = None
-
-                            # Prefer the timelapse last-frame source when a timelapse was
-                            # recording — it captures the moment after the toolhead parks
-                            # but before the bed drops, which the live-camera grab below
-                            # would miss (#1397). Skipped for external cameras (those have
-                            # their own framing and don't see a Bambu timelapse). Only
-                            # runs when the USER explicitly enabled timelapse for this
-                            # print — #1721 removed Bambuddy's force-on at dispatch
-                            # because it caused per-layer nozzle parking on Smooth-mode
-                            # slicer profiles.
-                            prefer_timelapse_source = bool(data.get("timelapse_was_active")) and not (
-                                printer.external_camera_enabled and printer.external_camera_url
-                            )
+            if archive.file_path:
+                archive_dir = app_settings.base_dir / Path(archive.file_path).parent
+            else:
+                logger.warning("[PHOTO-BG] Archive %s has no file_path, using fallback dir", archive_id)
+                archive_dir = app_settings.archive_dir / str(archive.id)
+            photo_filename = None
+
+            # Prefer the timelapse last-frame source when a timelapse was
+            # recording — it captures the moment after the toolhead parks
+            # but before the bed drops, which the live-camera grab below
+            # would miss (#1397). Skipped for external cameras (those have
+            # their own framing and don't see a Bambu timelapse). Only
+            # runs when the USER explicitly enabled timelapse for this
+            # print — #1721 removed Bambuddy's force-on at dispatch
+            # because it caused per-layer nozzle parking on Smooth-mode
+            # slicer profiles.
+            prefer_timelapse_source = bool(data.get("timelapse_was_active")) and not (
+                printer.external_camera_enabled and printer.external_camera_url
+            )
 
-                            if prefer_timelapse_source:
-                                photo_filename = await _capture_finish_photo_from_timelapse(
-                                    archive_id=archive_id,
-                                    archive_dir=archive_dir,
-                                )
+            if prefer_timelapse_source:
+                photo_filename = await _capture_finish_photo_from_timelapse(
+                    archive_id=archive_id,
+                    archive_dir=archive_dir,
+                )
 
-                            # #1721: replacement framing path — on_finish_photo_moment
-                            # pre-captured a frame at the stage-22 / FINISH edge (toolhead
-                            # parked, bed not yet dropped) and cached the JPEG bytes in
-                            # _stage22_finish_frames. Consume them now so the saved photo
-                            # has the better framing instead of the post-bed-drop angle
-                            # the live-camera fallback below would give.
-                            if not photo_filename:
-                                # #1790: on the FINISH-state fallback path the producer
-                                # task is dispatched back-to-back with this consumer, so
-                                # a bare pop would race past with an empty result and
-                                # the RTSP fallback below would collide with the
-                                # producer's still-in-flight grab (single-client RTSP
-                                # on Bambu printers). Wait for the producer to finish
-                                # or give up before touching the cache.
-                                in_flight = _stage22_finish_in_flight.pop(printer_id, None)
-                                if in_flight is not None:
-                                    try:
-                                        await asyncio.wait_for(in_flight.wait(), timeout=20.0)
-                                    except asyncio.TimeoutError:
-                                        logger.warning(
-                                            "[PHOTO-BG] timed out waiting for stage-22 producer for printer %s — proceeding to fallback",
-                                            printer_id,
-                                        )
-                                cached_frame = _stage22_finish_frames.pop(printer_id, None)
-                                if cached_frame:
-                                    photos_dir = archive_dir / "photos"
-                                    photos_dir.mkdir(parents=True, exist_ok=True)
-                                    timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
-                                    photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
-                                    photo_path = photos_dir / photo_filename
-                                    await asyncio.to_thread(photo_path.write_bytes, cached_frame)
-                                    logger.info(
-                                        "[PHOTO-BG] Saved stage-22 pre-captured frame: %s (%d bytes)",
-                                        photo_filename,
-                                        len(cached_frame),
-                                    )
+            # #1721: replacement framing path — on_finish_photo_moment
+            # pre-captured a frame at the stage-22 / FINISH edge (toolhead
+            # parked, bed not yet dropped) and cached the JPEG bytes in
+            # _stage22_finish_frames. Consume them now so the saved photo
+            # has the better framing instead of the post-bed-drop angle
+            # the live-camera fallback below would give.
+            if not photo_filename:
+                # #1790: on the FINISH-state fallback path the producer
+                # task is dispatched back-to-back with this consumer, so
+                # a bare pop would race past with an empty result and
+                # the RTSP fallback below would collide with the
+                # producer's still-in-flight grab (single-client RTSP
+                # on Bambu printers). Wait for the producer to finish
+                # or give up before touching the cache.
+                in_flight = _stage22_finish_in_flight.pop(printer_id, None)
+                if in_flight is not None:
+                    try:
+                        await asyncio.wait_for(in_flight.wait(), timeout=20.0)
+                    except asyncio.TimeoutError:
+                        logger.warning(
+                            "[PHOTO-BG] timed out waiting for stage-22 producer for printer %s — proceeding to fallback",
+                            printer_id,
+                        )
+                cached_frame = _stage22_finish_frames.pop(printer_id, None)
+                if cached_frame:
+                    photos_dir = archive_dir / "photos"
+                    photos_dir.mkdir(parents=True, exist_ok=True)
+                    timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
+                    photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
+                    photo_path = photos_dir / photo_filename
+                    await asyncio.to_thread(photo_path.write_bytes, cached_frame)
+                    logger.info(
+                        "[PHOTO-BG] Saved stage-22 pre-captured frame: %s (%d bytes)",
+                        photo_filename,
+                        len(cached_frame),
+                    )
 
-                            # Fallback chain: external camera → buffered live frame →
-                            # fresh RTSP capture. Only runs if the timelapse path above
-                            # didn't already produce a photo.
-                            if not photo_filename:
-                                if printer.external_camera_enabled and printer.external_camera_url:
-                                    logger.info("[PHOTO-BG] Using external camera")
-                                    from backend.app.services.external_camera import capture_frame
-
-                                    frame_data = await capture_frame(
-                                        printer.external_camera_url,
-                                        printer.external_camera_type or "mjpeg",
-                                        snapshot_url=printer.external_camera_snapshot_url,
-                                    )
-                                    if frame_data:
-                                        photos_dir = archive_dir / "photos"
-                                        photos_dir.mkdir(parents=True, exist_ok=True)
-                                        timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
-                                        photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
-                                        photo_path = photos_dir / photo_filename
-                                        await asyncio.to_thread(photo_path.write_bytes, frame_data)
-                                        logger.info("[PHOTO-BG] Saved external camera frame: %s", photo_filename)
-                                else:
-                                    # Check if camera stream is active - use buffered frame to avoid freeze
-                                    # Check both RTSP streams (_active_streams) and chamber image streams (_active_chamber_streams)
-                                    active_for_printer = [k for k in _active_streams if k.startswith(f"{printer_id}-")]
-                                    active_chamber_for_printer = [
-                                        k for k in _active_chamber_streams if k.startswith(f"{printer_id}-")
-                                    ]
-                                    buffered_frame = get_buffered_frame(printer_id)
-
-                                    if (active_for_printer or active_chamber_for_printer) and buffered_frame:
-                                        # Use frame from active stream
-                                        logger.info("[PHOTO-BG] Using buffered frame from active stream")
-                                        photos_dir = archive_dir / "photos"
-                                        photos_dir.mkdir(parents=True, exist_ok=True)
-                                        timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
-                                        photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
-                                        photo_path = photos_dir / photo_filename
-                                        await asyncio.to_thread(photo_path.write_bytes, buffered_frame)
-                                        logger.info("[PHOTO-BG] Saved buffered frame: %s", photo_filename)
-                                    else:
-                                        # No active stream - capture new frame
-                                        from backend.app.services.camera import capture_finish_photo
-
-                                        photo_filename = await capture_finish_photo(
-                                            printer_id=printer_id,
-                                            ip_address=printer.ip_address,
-                                            access_code=printer.access_code,
-                                            model=printer.model,
-                                            archive_dir=archive_dir,
-                                        )
+            # Fallback chain: external camera → buffered live frame →
+            # fresh RTSP capture. Only runs if the timelapse path above
+            # didn't already produce a photo.
+            if not photo_filename:
+                if printer.external_camera_enabled and printer.external_camera_url:
+                    logger.info("[PHOTO-BG] Using external camera")
+                    from backend.app.services.external_camera import capture_frame
+
+                    frame_data = await capture_frame(
+                        printer.external_camera_url,
+                        printer.external_camera_type or "mjpeg",
+                        snapshot_url=printer.external_camera_snapshot_url,
+                    )
+                    if frame_data:
+                        photos_dir = archive_dir / "photos"
+                        photos_dir.mkdir(parents=True, exist_ok=True)
+                        timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
+                        photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
+                        photo_path = photos_dir / photo_filename
+                        await asyncio.to_thread(photo_path.write_bytes, frame_data)
+                        logger.info("[PHOTO-BG] Saved external camera frame: %s", photo_filename)
+                else:
+                    # Check if camera stream is active - use buffered frame to avoid freeze
+                    # Check both RTSP streams (_active_streams) and chamber image streams (_active_chamber_streams)
+                    active_for_printer = [k for k in _active_streams if k.startswith(f"{printer_id}-")]
+                    active_chamber_for_printer = [k for k in _active_chamber_streams if k.startswith(f"{printer_id}-")]
+                    buffered_frame = get_buffered_frame(printer_id)
+
+                    if (active_for_printer or active_chamber_for_printer) and buffered_frame:
+                        # Use frame from active stream
+                        logger.info("[PHOTO-BG] Using buffered frame from active stream")
+                        photos_dir = archive_dir / "photos"
+                        photos_dir.mkdir(parents=True, exist_ok=True)
+                        timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
+                        photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
+                        photo_path = photos_dir / photo_filename
+                        await asyncio.to_thread(photo_path.write_bytes, buffered_frame)
+                        logger.info("[PHOTO-BG] Saved buffered frame: %s", photo_filename)
+                    else:
+                        # No active stream - capture new frame
+                        from backend.app.services.camera import capture_finish_photo
 
-                            if photo_filename:
-                                photos = archive.photos or []
-                                photos.append(photo_filename)
-                                archive.photos = photos
-                                await db.commit()
-                                logger.info("[PHOTO-BG] Saved: %s", photo_filename)
+                        photo_filename = await capture_finish_photo(
+                            printer_id=printer_id,
+                            ip_address=printer.ip_address,
+                            access_code=printer.access_code,
+                            model=printer.model,
+                            archive_dir=archive_dir,
+                        )
 
-                            if photo_filename:
-                                return photo_filename
+            # Write phase: attach the photo in a fresh short-lived session.
+            if photo_filename:
+                async with async_session() as db:
+                    from backend.app.models.archive import PrintArchive
+
+                    arch = await db.get(PrintArchive, archive_id)
+                    if arch is not None:
+                        photos = arch.photos or []
+                        photos.append(photo_filename)
+                        arch.photos = photos
+                        await db.commit()
+                logger.info("[PHOTO-BG] Saved: %s", photo_filename)
+                return photo_filename
             return None
         except Exception as e:
             logger.warning("[PHOTO-BG] Failed: %s", e)