From c1d25af7f1625c6bed5ee85ec380cdd5fb342f51 Mon Sep 17 00:00:00 2001 From: maziggy Date: Thu, 16 Jul 2026 09:07:07 +0200 Subject: [PATCH] fix(finish-photo): release DB connection during the camera capture (#2572) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- CHANGELOG.md | 1 + backend/app/main.py | 266 +++++++++++++++++++++++--------------------- 2 files changed, 138 insertions(+), 129 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index aed9eaf48..36267c96d 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/backend/app/main.py b/backend/app/main.py index dd308c9e3..46c8f1113 100644 --- a/backend/app/main.py +++ b/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 not printer or not archive: + return None - if printer and archive_id: - from backend.app.models.archive import PrintArchive + import uuid + from datetime import datetime + from pathlib import Path - result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id)) - archive = result.scalar_one_or_none() + 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 - if archive: - import uuid - from datetime import datetime - from pathlib import Path + # 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 + if prefer_timelapse_source: + photo_filename = await _capture_finish_photo_from_timelapse( + archive_id=archive_id, + archive_dir=archive_dir, + ) - # 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 - ) + # #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), + ) - if prefer_timelapse_source: - photo_filename = await _capture_finish_photo_from_timelapse( - archive_id=archive_id, - 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 - # #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), - ) + 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) - # 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 + 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 - 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) + 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 (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 + # 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 - 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: - photos = archive.photos or [] - photos.append(photo_filename) - archive.photos = photos - await db.commit() - logger.info("[PHOTO-BG] Saved: %s", photo_filename) - - if photo_filename: - return photo_filename + 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)