From afcea50eb72392d37e6891d9affa518b26a61cd7 Mon Sep 17 00:00:00 2001 From: maziggy Date: Thu, 16 Jul 2026 08:58:54 +0200 Subject: [PATCH] fix(timelapse): don't hold a DB connection across the FTP scan (#2572) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit _scan_for_timelapse_with_retries opened one session and held it across the FTP directory listing and the multi-MB video download — once per retry attempt, per completed print — pinning a pooled connection idle-in-transaction for the whole transfer. Read the archive + printer in a short session, release it, do the FTP list/download with no session held, then re-open a fresh short session only to attach the file. Existing scan tests already cover the read/download/attach path. --- CHANGELOG.md | 1 + backend/app/main.py | 123 ++++++++++++++++++++++++-------------------- 2 files changed, 67 insertions(+), 57 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4b0ce5bbc..aed9eaf48 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 +- **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. - **P1S camera still black on every page load, recovering only after ~20 minutes (#2521, reporter @nnimby848)** — The previous round of fixes did not take, and the reporter re-tested on two daily builds to say so. The fan-out barrier added last time — a replacement stream waits for the displaced one's socket to close before dialling, so a printer that allows a single camera connection never sees two at once — was correct, and was being **bypassed**. `shutdown_broadcaster()` *popped* the broadcaster out of the registry and only then awaited its teardown, so for the duration of the socket close the registry slot sat empty. A `/camera/stream` request landing in that window found nothing, minted a broadcaster with no predecessor to wait for, and dialled port 6000 immediately. The barrier only engages when the displaced broadcaster is still findable — and the one path that tears a stream down on purpose removed it first, disabling the barrier in exactly the case it was written for. A page reload fires `/camera/stop` and the new `/camera/stream` **concurrently**, which is why it reproduced on essentially every load. The printer then held two connections, kept feeding the orphan, and starved the live viewer: the new socket connects (the reporter's logs show `Chamber image: connected`) and then receives nothing until the printer's TCP keepalive reaps the dead one — **his 20 minutes, to the minute**. The stopped broadcaster now stays in the registry so the next viewer chains behind its socket close, which is what the barrier always intended. Pinned by a test that counts *actual* sockets through the real stop-then-restream race and fails with `2` against the old code; the existing barrier tests placed the broadcaster into the registry by hand, which is precisely why they never caught this. diff --git a/backend/app/main.py b/backend/app/main.py index 823a5dcc8..dd308c9e3 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -3554,10 +3554,14 @@ async def _scan_for_timelapse_with_retries(archive_id: int, baseline_names: set[ await asyncio.sleep(delay) try: - async with async_session() as db: - from backend.app.models.printer import Printer - from backend.app.services.bambu_ftp import download_file_bytes_async + from backend.app.models.printer import Printer + from backend.app.services.bambu_ftp import download_file_bytes_async + # Read phase: fetch archive + printer in a short session and release + # the pooled connection BEFORE the FTP list/download below. Holding it + # across the FTP round-trips left one connection idle-in-transaction per + # in-flight scan — ×4 retries, per completed print (issue #2572). + async with async_session() as db: service = ArchiveService(db) archive = await service.get_archive(archive_id) @@ -3574,46 +3578,49 @@ async def _scan_for_timelapse_with_retries(archive_id: int, baseline_names: set[ logger.warning("[TIMELAPSE] Printer not found for archive %s, stopping retries", archive_id) return - video_files, found_path = await _list_timelapse_videos(printer) + # I/O phase (no DB connection held): FTP list + download. + video_files, found_path = await _list_timelapse_videos(printer) - if not video_files: - logger.info("[TIMELAPSE] Attempt %s: No video files found, will retry", attempt) - continue + if not video_files: + logger.info("[TIMELAPSE] Attempt %s: No video files found, will retry", attempt) + continue - logger.info("[TIMELAPSE] Attempt %s: Found %s video files in %s", attempt, len(video_files), found_path) - for f in video_files[:5]: - logger.info("[TIMELAPSE] - %s", f.get("name")) + logger.info("[TIMELAPSE] Attempt %s: Found %s video files in %s", attempt, len(video_files), found_path) + for f in video_files[:5]: + logger.info("[TIMELAPSE] - %s", f.get("name")) - # Find files that are NEW (not in baseline snapshot) - new_files = [f for f in video_files if f.get("name", "") not in baseline_names] + # Find files that are NEW (not in baseline snapshot) + new_files = [f for f in video_files if f.get("name", "") not in baseline_names] - if new_files: - # Pick the first new file (there should typically be exactly one) - target = new_files[0] - file_name = target.get("name") - remote_path = target.get("path") or f"/timelapse/{file_name}" - logger.info( - "[TIMELAPSE] Attempt %s: New file detected: %s (downloading for archive %s)", - attempt, - file_name, - archive_id, - ) + if new_files: + # Pick the first new file (there should typically be exactly one) + target = new_files[0] + file_name = target.get("name") + remote_path = target.get("path") or f"/timelapse/{file_name}" + logger.info( + "[TIMELAPSE] Attempt %s: New file detected: %s (downloading for archive %s)", + attempt, + file_name, + archive_id, + ) - timelapse_data = await download_file_bytes_async( - printer.ip_address, printer.access_code, remote_path, printer_model=printer.model - ) - if timelapse_data: - success = await service.attach_timelapse(archive_id, timelapse_data, file_name) - if success: - logger.info("[TIMELAPSE] Successfully attached timelapse to archive %s", archive_id) - await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True}) - return - else: - logger.warning("[TIMELAPSE] Failed to attach timelapse to archive %s", archive_id) + timelapse_data = await download_file_bytes_async( + printer.ip_address, printer.access_code, remote_path, printer_model=printer.model + ) + if timelapse_data: + # Write phase: attach in a fresh short-lived session. + async with async_session() as db: + success = await ArchiveService(db).attach_timelapse(archive_id, timelapse_data, file_name) + if success: + logger.info("[TIMELAPSE] Successfully attached timelapse to archive %s", archive_id) + await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True}) + return else: - logger.warning("[TIMELAPSE] Attempt %s: Failed to download new file, will retry", attempt) + logger.warning("[TIMELAPSE] Failed to attach timelapse to archive %s", archive_id) else: - logger.info("[TIMELAPSE] Attempt %s: No new files since baseline, will retry", attempt) + logger.warning("[TIMELAPSE] Attempt %s: Failed to download new file, will retry", attempt) + else: + logger.info("[TIMELAPSE] Attempt %s: No new files since baseline, will retry", attempt) except Exception as e: logger.warning("[TIMELAPSE] Attempt %s failed with error: %s", attempt, e) @@ -3622,10 +3629,11 @@ async def _scan_for_timelapse_with_retries(archive_id: int, baseline_names: set[ if base_name: logger.info("[TIMELAPSE] Retries exhausted, trying name-match fallback for '%s'", base_name) try: - async with async_session() as db: - from backend.app.models.printer import Printer - from backend.app.services.bambu_ftp import download_file_bytes_async + from backend.app.models.printer import Printer + from backend.app.services.bambu_ftp import download_file_bytes_async + # Read phase: short session, released before the FTP work (issue #2572). + async with async_session() as db: service = ArchiveService(db) archive = await service.get_archive(archive_id) if not archive or archive.timelapse_path: @@ -3636,25 +3644,26 @@ async def _scan_for_timelapse_with_retries(archive_id: int, baseline_names: set[ if not printer: return - video_files, found_path = await _list_timelapse_videos(printer) - for f in video_files: - fname = f.get("name", "") - if base_name.lower() in fname.lower(): - remote_path = f.get("path") or f"/timelapse/{fname}" - logger.info("[TIMELAPSE] Name-match fallback: '%s' matches '%s'", base_name, fname) + # I/O phase (no DB connection held): FTP list + download. + video_files, found_path = await _list_timelapse_videos(printer) + for f in video_files: + fname = f.get("name", "") + if base_name.lower() in fname.lower(): + remote_path = f.get("path") or f"/timelapse/{fname}" + logger.info("[TIMELAPSE] Name-match fallback: '%s' matches '%s'", base_name, fname) - timelapse_data = await download_file_bytes_async( - printer.ip_address, printer.access_code, remote_path, printer_model=printer.model - ) - if timelapse_data: - success = await service.attach_timelapse(archive_id, timelapse_data, fname) - if success: - logger.info( - "[TIMELAPSE] Name-match fallback attached timelapse to archive %s", archive_id - ) - await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True}) - return - break # Only try the first name match + timelapse_data = await download_file_bytes_async( + printer.ip_address, printer.access_code, remote_path, printer_model=printer.model + ) + if timelapse_data: + # Write phase: attach in a fresh short-lived session. + async with async_session() as db: + success = await ArchiveService(db).attach_timelapse(archive_id, timelapse_data, fname) + if success: + logger.info("[TIMELAPSE] Name-match fallback attached timelapse to archive %s", archive_id) + await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True}) + return + break # Only try the first name match except Exception as e: logger.warning("[TIMELAPSE] Name-match fallback failed: %s", e)