fix(cover): release the DB connection before the FTP thumbnail download (#2572)

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.
This commit is contained in:
maziggy 2026-07-16 13:55:19 +02:00
parent c4d077c08f
commit bab4c1e19b
6 changed files with 126 additions and 6 deletions

View file

@ -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.

View file

@ -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")

View file

@ -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

View file

@ -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,
)

View file

@ -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."""

View file

@ -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."""