Explorar o código

fix(timelapse): don't hold a DB connection across the FTP scan (#2572)

_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.
maziggy hai 1 mes
pai
achega
afcea50eb7
Modificáronse 2 ficheiros con 67 adicións e 57 borrados
  1. 1 0
      CHANGELOG.md
  2. 66 57
      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
+- **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.

+ 66 - 57
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)