From bab4c1e19b4197d253f2cae7e379ee31ee47c4fb Mon Sep 17 00:00:00 2001 From: maziggy Date: Thu, 16 Jul 2026 13:55:19 +0200 Subject: [PATCH] fix(cover): release the DB connection before the FTP thumbnail download (#2572) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GET /printers/{id}/cover took its printer row via Depends(get_db), whose yield-dependency session stays open for the whole request — including the 3MF cover download (up to 8 remote paths x retries with backoff, minutes under FTP contention). One pooled connection sat idle-in-transaction the entire time; on a large farm a wall of dashboards drained the pool. The route now fetches the printer in a short-lived async_session() and releases the connection before the download (expire_on_commit=False keeps printer.* readable). Pinned by a signature-inspection guard that fails if get_db is ever re-added. fix(print-start): release the DB connection across plate detection and 3MF download (#2572) on_print_start held one session from top to bottom of the handler, across two slow I/O blocks that need no database: the plate-detection camera grab and, on the new-archive path, the multi-path 3MF FTP download (its own comments cite worst cases of tens of minutes). The connection sat idle-in- transaction for both, once per starting print. It now commits at each boundary — only read SELECTs have run on those paths (every write branch returns earlier), so the commit persists nothing and simply returns the connection to the pool for the I/O; the next query re-acquires, and expire_on_commit=False keeps printer.* readable. fix(startup): connect to printers concurrently so the API serves within seconds (#2572) init_printer_connections awaited each printer's connection serially, and connect_printer ends in a fixed 1s settle wait. The MQTT connect is non- blocking (connect_async + loop_start), so that 1s x fleet size was pure serial dead air the FastAPI lifespan blocked on before uvicorn began serving — ~100s before port 8000 responded on a 93-printer farm. The connections are now started with asyncio.gather, so the step takes ~1s regardless of fleet size. return_exceptions=True isolates each result: one unreachable printer no longer aborts the rest, or startup itself. --- CHANGELOG.md | 3 ++ backend/app/api/routes/printers.py | 19 +++++++++-- backend/app/main.py | 20 +++++++++++ backend/app/services/printer_manager.py | 33 +++++++++++++++++-- .../tests/integration/test_printers_api.py | 26 +++++++++++++++ .../unit/services/test_printer_manager.py | 31 +++++++++++++++++ 6 files changed, 126 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6c71e03bc..f48c2a01d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,9 @@ All notable changes to Bambuddy will be documented in this file. ## [1.2.5b2] - Unreleased ### Fixed +- **The API didn't start serving for ~100 seconds on a large farm while it connected to printers one at a time (#2572, reporter @Jostxxl)** — On the reporter's 93-printer farm port 8000 didn't respond until roughly 100 seconds after the service started. The cause was in the FastAPI lifespan: `init_printer_connections` looped over every active printer and `await`ed each connection *serially*, and each `connect_printer` ends in a fixed one-second settle wait. The MQTT connect itself is non-blocking — `BambuMQTTClient.connect()` only calls `connect_async()` + `loop_start()`, so the handshake runs on a background thread — which means that one-second wait, times the fleet size, was pure serial dead air that the lifespan blocked on *before* the ASGI server began accepting requests. The connections are now started concurrently with `asyncio.gather`, so the whole step takes about a second regardless of how many printers you run, and the dashboard is reachable almost immediately. Each connection's result is also isolated (`return_exceptions=True`): a single unreachable printer no longer aborts the rest — or, as the old un-guarded serial `await` allowed, the entire startup. The MQTT clients still connect in the background exactly as before; only the startup wait is parallelized. +- **The print-start handler held a DB connection open across plate detection and the 3MF download (#2572, reporter @Jostxxl)** — After farm-testing the first round of #2572 fixes the reporter still saw `idle in transaction` sessions lasting minutes, and traced one to `on_print_start`: its last statement was `SELECT print_archives…`, immediately followed in the log by the printer's own `on_print_start` → `Trying filenames` → FTP work. The handler opened a single database session at the top and held it to the very end of the function — across two slow I/O blocks that need no database: the optional plate-detection camera capture (a 2.5s chamber-light settle plus an FTP/RTSP grab) and, on the new-archive path, the 3MF FTP download itself (up to five remote paths per candidate filename, each with retry/backoff — the code's own comments cite worst cases of tens of minutes under FTP contention). So one pooled connection sat idle-in-transaction for the whole of both, once per starting print, and print starts cluster on a farm. The connection is now released at both boundaries: reaching either point, only read `SELECT`s have run on that path (every write branch returns earlier), so a commit persists nothing and simply ends the read transaction, returning the connection to the pool for the duration of the I/O; the next query re-acquires a fresh one, and `expire_on_commit=False` keeps the already-loaded `printer.*` columns readable with no lazy load. Behaviour is unchanged. Continues the #2572 effort (camera stream, timelapse scan, finish photo, notification snapshots) to stop holding sessions across slow I/O. +- **The printer-cover endpoint held a DB connection open across the FTP thumbnail download (#2572, reporter @Jostxxl)** — The reporter's second correlation: a transaction whose last statement was `SELECT printers…`, matched in the log to the cover route (`Cover: resolved plate …` / `Trying to download cover … (trying 4 paths)`), still open more than three and a half minutes later. `GET /printers/{id}/cover` took its printer row via `Depends(get_db)`, and `get_db` is a `yield` dependency — its session stays open for the whole request, including the cover's 3MF download (up to eight remote paths × retries with backoff, minutes under the same single-FTP-socket contention that produces the 425s). The session was used for exactly one `SELECT`; everything after reads already-loaded `printer.*` scalars, `printer_manager`, and FTP/zip — no database. The endpoint now fetches the printer in a short-lived session and releases the connection *before* the download (`expire_on_commit=False` keeps the columns readable), mirroring the camera-stream fix. Pinned by a regression test that fails if a `get_db`-held session is ever re-added to the route. - **Queue polling re-parsed every 3MF from scratch on each poll (#2573, reporter @Jostxxl)** — The Queue page polls `GET /api/v1/queue/` every few seconds, and for each item with a `plate_id` the serializer called three separate helpers — `extract_print_time_from_3mf`, `extract_filament_usage_from_3mf`, `extract_bed_type_from_3mf` — each of which independently opened the item's ZIP and re-parsed `Metadata/slice_info.config`. With 22 queued items that is 66 ZIP-open + XML-parse operations per poll, run in the event-loop thread, repeated for *every* connected browser even though the files never changed. The three values now come from a single combined parse (`extract_plate_metadata_from_3mf`) cached by file revision — the key is `(path, plate_id, mtime_ns, size)`, so an unchanged file is parsed at most once and a replaced or edited file transparently re-parses with no manual invalidation. The three legacy helpers still exist (other callers use them) but now delegate to the same cached parse, so usage-tracking and Spoolman paths benefit too; the queue hot path calls the combined helper once per row. The cache is a bounded (512-entry) LRU guarded by a lock so it stays small and is safe from worker threads. Listing an unchanged queue now serializes DB data and does no repeat 3MF parsing. (The reporter's broader farm-scale asks — a WebSocket-delta queue, an initial snapshot endpoint, ETag/304 support, per-row plate-request batching — are a separate queue-page redesign, not part of this fix.) - **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. diff --git a/backend/app/api/routes/printers.py b/backend/app/api/routes/printers.py index 89690dd99..30ffc5740 100644 --- a/backend/app/api/routes/printers.py +++ b/backend/app/api/routes/printers.py @@ -8,6 +8,7 @@ from fastapi.responses import Response from sqlalchemy import func, select from sqlalchemy.ext.asyncio import AsyncSession +from backend.app.core import database from backend.app.core.auth import ( RequireCameraStreamTokenIfAuthEnabled, RequirePermissionIfAuthEnabled, @@ -952,7 +953,6 @@ def clear_cover_cache(printer_id: int) -> None: async def get_printer_cover( printer_id: int, view: str | None = None, - db: AsyncSession = Depends(get_db), _: None = RequireCameraStreamTokenIfAuthEnabled, ): """Get the cover image for the current print job. @@ -961,8 +961,21 @@ async def get_printer_cover( view: Optional view type. Use "top" for top-down build plate view (useful for skip objects). Default returns angled 3D perspective view. """ - result = await db.execute(select(Printer).where(Printer.id == printer_id)) - printer = result.scalar_one_or_none() + # Fetch the printer in a short-lived session and release the pooled DB + # connection BEFORE the FTP download below. Previously this route took its + # row via Depends(get_db), whose session stays open for the whole request — + # so a 3MF cover download (up to 8 paths × 3 retries with backoff, minutes + # under FTP contention) pinned one pooled connection idle-in-transaction the + # entire time (issue #2572). db is used only for this one SELECT; everything + # after reads already-loaded printer.* scalars (expire_on_commit=False keeps + # them readable), printer_manager, and FTP/zip — no lazy loads. + # + # Reference async_session via the module so the maker is looked up at call + # time — keeps it in sync with reinitialize_database() and lets the test + # harness's patch of backend.app.core.database.async_session take effect. + async with database.async_session() as db: + result = await db.execute(select(Printer).where(Printer.id == printer_id)) + printer = result.scalar_one_or_none() if not printer: raise HTTPException(404, "Printer not found") diff --git a/backend/app/main.py b/backend/app/main.py index 6f7d9c246..003cb5398 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -2418,6 +2418,14 @@ async def on_print_start(printer_id: int, data: dict): ) if printer and printer.plate_detection_enabled: logger.info("[PLATE CHECK] ENTERING plate detection code for printer %s", printer_id) + # Release the pooled DB connection before the plate-detection camera + # work (a 2.5s light-settle sleep + FTP/camera capture). Only the + # printer SELECT has run so far — nothing to persist — so this commit + # is a data-noop that ends the read transaction and returns the + # connection to the pool during the I/O (issue #2572). expire_on_commit + # =False keeps printer.* readable; on_plate_not_empty (rare) and the + # archive lookups below re-acquire a fresh connection on next execute. + await db.commit() try: from backend.app.services.plate_detection import check_plate_empty @@ -2941,6 +2949,18 @@ async def on_print_start(printer_id: int, data: dict): logger.info("Trying filenames: %s", possible_names) + # Release the pooled DB connection before the 3MF FTP download. Reaching + # here means none of the expected-/existing-archive write branches ran + # (they all return earlier) — only SELECTs have executed on this path, so + # this commit persists nothing; it ends the read transaction so the + # connection returns to the pool during the download. That download tries + # up to five remote paths per candidate filename with retry/backoff and + # can run for minutes under FTP contention; holding the session across it + # pinned one pooled connection idle-in-transaction (issue #2572). No DB + # work runs during the download — the new-archive writes below re-acquire + # a fresh connection, and expire_on_commit=False keeps printer.* readable. + await db.commit() + # Try to find and download the 3MF file temp_path = None downloaded_filename = None diff --git a/backend/app/services/printer_manager.py b/backend/app/services/printer_manager.py index 5d24657d7..2179c3973 100644 --- a/backend/app/services/printer_manager.py +++ b/backend/app/services/printer_manager.py @@ -1320,9 +1320,36 @@ printer_manager = PrinterManager() async def init_printer_connections(db: AsyncSession): - """Initialize connections to all active printers.""" + """Initialize connections to all active printers. + + Connections are started concurrently. ``connect_printer()`` is non-blocking + apart from a fixed 1-second settle wait — ``BambuMQTTClient.connect()`` only + calls ``connect_async()`` + ``loop_start()``, so the handshake happens on a + background thread and the coroutine's only real cost is that ``sleep(1)``. A + serial loop therefore spent one whole second per printer inside the FastAPI + lifespan *before* the ASGI server begins serving: on a large farm that was + ~100s of dead air before port 8000 responded (issue #2572, reporter's + 93-printer farm). Gathering overlaps the settle waits so the whole step takes + ~1s regardless of fleet size. Exceptions are isolated per printer with + ``return_exceptions=True`` so one unreachable row can't abort the rest — or + startup itself, which the old serial loop's un-caught await would have done. + + All columns ``connect_printer`` reads are eagerly loaded by the SELECT above + and touched synchronously before its trailing ``await``, so no concurrent + lazy-load is triggered on the shared session. + """ result = await db.execute(select(Printer).where(Printer.is_active.is_(True))) printers = result.scalars().all() - for printer in printers: - await printer_manager.connect_printer(printer) + outcomes = await asyncio.gather( + *(printer_manager.connect_printer(printer) for printer in printers), + return_exceptions=True, + ) + for printer, outcome in zip(printers, outcomes, strict=True): + if isinstance(outcome, Exception): + logger.warning( + "Failed to connect printer %s (%s) at startup: %s", + printer.id, + printer.name, + outcome, + ) diff --git a/backend/tests/integration/test_printers_api.py b/backend/tests/integration/test_printers_api.py index a6f8f9000..bb9abf1bc 100644 --- a/backend/tests/integration/test_printers_api.py +++ b/backend/tests/integration/test_printers_api.py @@ -571,6 +571,32 @@ class TestPrintersAPI: # ======================================================================== +class TestCoverPoolHygiene: + """Regression guard for the /cover DB-connection leak (issue #2572).""" + + def test_cover_does_not_hold_a_get_db_session(self): + """The cover endpoint must NOT take a ``Depends(get_db)`` session. + + ``get_db`` is a ``yield`` dependency, so its session stays open for the + whole request — including the 3MF cover download (up to 8 remote paths × + retries with backoff, minutes under FTP contention), pinning one pooled + DB connection ``idle in transaction`` the entire time. The endpoint + fetches the printer in a short-lived ``async with async_session()`` and + releases the connection before the FTP work. If someone re-adds a + ``Depends(get_db)`` param, this fails. + """ + import inspect + + from backend.app.api.routes.printers import get_db, get_printer_cover + + for name, param in inspect.signature(get_printer_cover).parameters.items(): + dependency = getattr(param.default, "dependency", None) + assert dependency is not get_db, ( + f"get_printer_cover re-introduced a get_db-held session via parameter {name!r} — " + "it would stay open for the entire FTP cover download (issue #2572)" + ) + + class TestPrinterDataIntegrity: """Tests for printer data integrity.""" diff --git a/backend/tests/unit/services/test_printer_manager.py b/backend/tests/unit/services/test_printer_manager.py index 957d5421e..e5669056e 100644 --- a/backend/tests/unit/services/test_printer_manager.py +++ b/backend/tests/unit/services/test_printer_manager.py @@ -1804,6 +1804,37 @@ class TestInitPrinterConnections: mock_manager.connect_printer.assert_not_called() + @pytest.mark.asyncio + async def test_one_failing_printer_does_not_abort_the_rest(self): + """A single unreachable printer must not abort startup or the others (#2572). + + The connections are gathered with return_exceptions=True. The old serial + ``await`` loop had no error handling, so the first printer that raised + propagated straight out of init_printer_connections and failed the + FastAPI lifespan — taking the whole app down over one bad row, and + skipping every printer after it. This asserts the isolation: every + printer is still attempted and the exception never escapes. + """ + mock_db = AsyncMock() + printers = [MagicMock(id=i, name=f"p{i}", is_active=True) for i in range(3)] + mock_result = MagicMock() + mock_result.scalars.return_value.all.return_value = printers + mock_db.execute.return_value = mock_result + + async def connect(printer): + if printer.id == 1: + raise ConnectionError("printer 1 is unreachable") + return True + + with patch("backend.app.services.printer_manager.printer_manager") as mock_manager: + mock_manager.connect_printer = AsyncMock(side_effect=connect) + + # Must not raise despite printer 1 failing. + await init_printer_connections(mock_db) + + # All three were still attempted (not aborted at the failing one). + assert mock_manager.connect_printer.call_count == 3 + class TestAmsChangeCallback: """Tests for AMS change callback functionality."""