diff --git a/CHANGELOG.md b/CHANGELOG.md index 0e2ccbec0..6d4720ae2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,6 +17,7 @@ All notable changes to Bambuddy will be documented in this file. - **Queue edit showed the sliced-for model as the scheduler target, and a cross-model queue row could dispatch G-code to an incompatible printer (#2578, reporter @Jostxxl)** — Two bugs with one root. The "Any \" assignment button labeled itself from the file's slice metadata while the scheduler actually used the row's `target_model`, so an X1C-sliced item targeting H2D read "Any X1C" above "Scheduler will assign to first available idle H2D printer". Worse, the mismatch could be *created* silently: the sliced-for model loads asynchronously, and clicking "Any Model" before it arrived pre-selected the first model alphabetically — on a mixed X1C/P1S/H2D farm that's H2D — after which the model dropdown hid itself, leaving no way to see or fix the wrong target. Nothing downstream checked compatibility, so the scheduler would happily hand X1C G-code to an H2D. Now: the target model is never silently defaulted (the dropdown stays visible in model mode, pre-selected to the sliced-for model when available, and back-fills once the metadata loads); the button reflects the actual target; a warning shows when the target differs from the sliced-for model. Compatibility is enforced end-to-end with an explicit G-code interchange family table (X1/X1C/X1E/P1P/P1S interchange; everything else exact-match — files without slice metadata are never blocked): incompatible models are disabled in the dropdown, queue create/update reject a mismatch with a clear 400 (so API-created rows can't sneak in), and the scheduler holds back pre-existing mismatched rows with an actionable waiting reason instead of dispatching them — fix the target via edit and the job flows again. - **Manual jog could drive an axis past its travel limit into a collision (#2579, reporter @R3play210)** — Jog the bed up from Bambuddy and, instead of stopping at the travel limit, it keeps going until the nozzle hits the plate; X/Y overrun too, on every model. Instrumenting the exact bytes sent to an H2D showed Bambuddy issuing a clean, correct move at the limit — `G91` / `G1 Z-1.00 F600` / `G90`, no endstop manipulation — that the printer executed straight past the stop, while the machine's **own touchscreen refuses the identical motion**. **This is a Bambu firmware bug: the firmware does not enforce its soft endstops on G-code received over MQTT** (the path every remote tool, Bambuddy included, must use), and it reports no axis position, so Bambuddy cannot know where the bed is to stop it either. It is not fixable from our side. Two things change here: (1) the jog no longer wraps moves in `M211 S0`/`S1` — the old code disabled the firmware's soft endstops *globally* around every jog, which also broke the **touchscreen's** limits until the printer was power-cycled; it now sends a bare move and never touches `M211`, so the touchscreen stays protected. (2) The jog panel now shows a prominent warning that travel limits are **not** enforced during manual moves because of this firmware bug, so nobody trusts the control to stop at the limit. Client-side travel-limit enforcement (dead-reckoning from a home) is tracked separately as the only real mitigation. If your printer currently overruns even from its touchscreen, power-cycle it once to restore the endstops an older Bambuddy build disabled. - **External spool kept its old inventory filament after the type was changed on the printer (#2575, reporter @ajbastien)** — Assigning a new filament to the external spool (e.g. generic ABS in place of generic TPU) left the previous inventory spool assigned, so an ABS spool stayed mapped to TPU. The reconciliation that unlinks a stale external-spool assignment lives in `on_ams_change`, but that callback only fired on changes to the regular AMS units — its change-hash never included the external spool (`vt_tray`/`vir_slot`), and the external-spool data is stored after the AMS handler runs. External-spool identity changes (type, colour, tag, or a reset to empty) now re-trigger the callback so the stale assignment is unlinked; the fill-percentage (`remain`) is deliberately excluded from the fingerprint so a running print doesn't fire it on every push. Follow-up: the auto-unlink now also broadcasts `spool_assignment_changed` for each cleared slot — previously only the manual assign/unassign endpoints did, so an open browser kept rendering the now-unlinked spool on the slot until an unrelated refetch, which read as "the fix didn't work" even though the server state was already correct (reporter confirmed a browser refresh showed the right state all along). +- **Two or three users opening the UI at once exhausted the PostgreSQL connection pool immediately (#2572, reporter @Jostxxl)** — Even after the session-hygiene fixes below, the reporter's 93-printer farm saturated the pool the moment a couple of clients logged in together: the log filled with `QueuePool limit of size 10 overflow 20 reached, connection timed out` from `permission_checker` / `is_jti_revoked` / `is_auth_enabled`, and every one of the 30 stuck sessions was `idle in transaction` with the same last statement — the `auth_enabled` settings `SELECT`. Three things had regressed on `dev` after an earlier configurable-pool change was reverted and never re-landed (only the route-by-route session fixes were). **(a) The pool was back to a hard-coded, farm-hostile size.** PostgreSQL ran on `pool_size=10 + max_overflow=20` (30 connections total) with no way to raise it; the `DB_POOL_SIZE` / `DB_MAX_OVERFLOW` / `DB_POOL_TIMEOUT` / `DB_POOL_RECYCLE` env knobs and the `GET /api/v1/system/db-pool` gauge were gone. The PostgreSQL default is again `20 + 80` (100) with `pool_pre_ping` and a 1800s `pool_recycle`, all env-overridable, and `/system/db-pool` is back (it reports resolved config + live checked-out/checked-in/overflow without itself checking out a connection, so it stays truthful under saturation). SQLite is unchanged at `20 + 200`. **(b) Every protected request re-queried `auth_enabled` from the database.** That per-request round-trip — the exact `SELECT` seen on all 30 stuck sessions — is back to being cached for 30s. The cache is deliberately one-directional: only an *enabled* result is ever cached, so a stale read can only make a request *require* auth that a moment ago didn't — it can never skip a check that is now required (staleness fails closed). Toggling auth invalidates it immediately; the TTL is only a backstop for out-of-band changes. **(c) Every authenticated request checked out two pooled connections, not one.** The permission dependencies already hold a session, but the revoked-`jti` check opened a *second* `async_session` on top of it — so a burst of concurrent logins (the SPA fires many protected endpoints at once) needed twice the connections it should. `is_jti_revoked` now accepts and reuses the caller's session; the two token dependencies that check the jti before they have a session open were restructured to open one first, so each authenticated request makes a single checkout. Covered by tests for the dialect-aware pool sizing + env overrides, the pool-status shape, the True-only fail-closed cache (enabled cached, disabled/unconfigured never cached, DB error propagates), and the jti check reusing a provided session versus opening its own. - **The file-manager, storage, camera-snapshot and timelapse routes still held a DB connection across their FTP/camera work (#2572, reporter @Jostxxl)** — After the earlier #2572 fixes the farm still bled connections over a long run — the pool crept from its normal ~14 to the full 300 across ~23 hours (with only ~20 of 93 printers powered on) and then threw `QueuePool limit … connection timed out`. These were the remaining routes of the same class: each took its printer row via `Depends(get_db)`, whose session stays open for the whole request, and then talked FTP to the printer — a listing, a multi-MB download, a delete, a storage probe — with a browser polling the cover/snapshot tiles for every card, offline ones included, and 73 unreachable printers each burning a full FTP timeout. The printer-files endpoints (`/files`, `/files/download`, `/files/gcode`, `/files/plates`, `/files/plate-thumbnail`, `/files/download-zip`, `DELETE /files`, `/storage`), the camera **snapshot** endpoint (sibling of the already-fixed stream), and the timelapse **scan** and **select** endpoints now read what they need in a short session, release the connection *before* the FTP/camera work (`expire_on_commit=False` keeps the loaded `printer.*` columns readable), and — for timelapse, which also writes — re-open a fresh short session only to attach the downloaded file. Behaviour is unchanged; the timelapse-scan boundary is pinned by a regression test that mocks the FTP listing/download and asserts both the detached-row reads and that the attach persists through the fresh session. Completes the route-by-route half of the #2572 effort (camera stream, cover, on_print_start, timelapse scan, finish photo, notification snapshots). - **Four async FTP helpers had no overall timeout, so a saturated FTP thread-pool could pin a caller — and any DB connection it held — indefinitely (#2572, reporter @Jostxxl)** — FTP runs in a fixed 48-worker thread pool. `download_file_try_paths_async`, `download_file_bytes_async`, `get_storage_info_async` and `delete_file_async` wrapped their worker in a bare `run_in_executor` with no `asyncio.wait_for` (unlike `list_files_async`/`download_file_async`, which already had one). The per-socket timeout only bounds a worker once it *starts*; it does nothing for the time a call spends **queued** waiting for a free worker. On a farm where offline printers keep every worker parked on dead connects, that queue wait is unbounded — so an awaiting coroutine, and any pooled DB connection it was still holding, could wait forever. All four now cap the whole operation with `asyncio.wait_for` (returning the same failure sentinel on expiry, the orphaned worker's result discarded), so a backed-up FTP pool can no longer pin a caller — defence-in-depth beneath the route fixes above. - **A wedged SMTP server could freeze the entire event loop during an email notification (#2572, reporter @Jostxxl)** — `_send_email` ran `smtplib` **synchronously on the event loop** and constructed the connection with **no timeout** (smtplib then falls back to the global socket timeout, which the app never sets). A relay that accepts the TCP connection but stalls on the greeting/login/DATA left the send blocked forever — and because it ran inline, it stalled every other coroutine with it. The send now runs off the loop (`asyncio.to_thread`) with an explicit 30s connect timeout, and `quit()` moved into a `finally` so a mid-send error can't leak the socket. Latent bug surfaced while auditing #2572; it presents as a stall/latency spike rather than the pool leak, but the same "blocking I/O on the loop" family. diff --git a/backend/app/api/routes/auth.py b/backend/app/api/routes/auth.py index de987af18..d72ecc384 100644 --- a/backend/app/api/routes/auth.py +++ b/backend/app/api/routes/auth.py @@ -189,9 +189,15 @@ async def set_advanced_auth_enabled(db: AsyncSession, enabled: bool) -> None: async def set_auth_enabled(db: AsyncSession, enabled: bool) -> None: """Set authentication enabled status.""" + from backend.app.core.auth import invalidate_auth_enabled_cache from backend.app.core.db_dialect import upsert_setting await upsert_setting(db, Settings, "auth_enabled", "true" if enabled else "false") + # Drop the cached auth-enabled flag so the change takes effect immediately + # instead of after the TTL (issue #2572). Safe pre-commit: only enabled=True + # is ever cached, and the newly-enabled True isn't visible to other sessions + # until this transaction commits, so no stale value can be re-cached here. + invalidate_auth_enabled_cache() # Note: Don't commit here - let get_db handle it or commit explicitly in the route @@ -659,7 +665,7 @@ async def get_current_user_info( headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): # B1: logout bypass fix + if not jti or await is_jti_revoked(jti, db): # B1: logout bypass fix raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", diff --git a/backend/app/api/routes/system.py b/backend/app/api/routes/system.py index 670ebe4f2..dd0c47aae 100644 --- a/backend/app/api/routes/system.py +++ b/backend/app/api/routes/system.py @@ -606,6 +606,24 @@ async def get_system_health( return await asyncio.to_thread(scan_logs, sensitive_strings=sensitive_strings) +@router.get("/db-pool") +async def get_db_pool( + _: User | None = RequirePermissionIfAuthEnabled(Permission.SYSTEM_READ), +): + """Live database connection-pool gauges for large-farm diagnostics (#2572). + + Reports the resolved pool configuration plus current checked-out / + checked-in / overflow counts. Deliberately takes no DB session — reading + the pool's own counters must not itself consume a connection, so this stays + truthful even when the pool is saturated. On a healthy install ``checked_out`` + sits well below ``config.pool_size + config.max_overflow``; sustained + saturation points at connections held across slow I/O (see #2572). + """ + from backend.app.core.database import get_pool_status + + return get_pool_status() + + @router.get("/appliance") async def get_appliance_defaults(): """Expose appliance-set state for the SPA's bootstrap surface. diff --git a/backend/app/core/auth.py b/backend/app/core/auth.py index 820e4ef0a..5d1e243dd 100644 --- a/backend/app/core/auth.py +++ b/backend/app/core/auth.py @@ -3,6 +3,7 @@ from __future__ import annotations import logging import os import secrets +import time from datetime import datetime, timedelta, timezone from typing import Annotated @@ -395,7 +396,7 @@ def require_energy_cost_update(): if username is None: raise credentials_exception jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise credentials_exception iat: int | float | None = payload.get("iat") except JWTError: @@ -798,10 +799,18 @@ async def revoke_jti(jti: str, expires_at: datetime, username: str | None = None await db.rollback() # jti already revoked — desired state, ignore -async def is_jti_revoked(jti: str) -> bool: - """Return True if the given jti has been revoked.""" - async with async_session() as db: - result = await db.execute( +async def is_jti_revoked(jti: str, db: AsyncSession | None = None) -> bool: + """Return True if the given jti has been revoked. + + Pass ``db`` to reuse the caller's session instead of opening a new one + (issue #2572): the permission dependencies already hold a session, and a + second checkout per request doubled pool pressure — a login burst then + exhausted the pool. With ``db`` omitted a short session is opened as before, + for callers that check the jti before they have a session open. + """ + + async def _query(session: AsyncSession) -> bool: + result = await session.execute( select(AuthEphemeralToken).where( AuthEphemeralToken.token == jti, AuthEphemeralToken.token_type == "revoked_jti", @@ -809,6 +818,11 @@ async def is_jti_revoked(jti: str) -> bool: ) return result.scalar_one_or_none() is not None + if db is not None: + return await _query(db) + async with async_session() as own_db: + return await _query(own_db) + async def get_user_by_username(db: AsyncSession, username: str) -> User | None: """Get a user by username (case-insensitive) with groups loaded for permission checks.""" @@ -862,6 +876,33 @@ async def authenticate_user_by_email(db: AsyncSession, email: str, password: str return user +# Short-lived cache for the auth-enabled flag (issue #2572). The middleware +# and every ownership/permission dependency probe this once (or more) per +# request; on a large farm that DB round-trip is pure overhead because the +# value changes only when an admin toggles auth. +# +# SECURITY: only a ``True`` (auth-enabled) result is EVER cached. A disabled / +# unconfigured result is never cached, so a stale cache can only ever cause a +# request to REQUIRE auth that a moment ago wasn't required — it can never skip +# an auth check that is now required. Staleness fails CLOSED, never open (cf. +# GHSA-6mf4-q26m-47pv). ``set_auth_enabled`` invalidates explicitly on any +# toggle; the TTL is only a backstop for out-of-band changes (a direct DB edit, +# or another worker process in a multi-worker deployment). +_AUTH_ENABLED_CACHE_TTL_SECONDS = 30.0 +_auth_enabled_cached_value: bool = False +_auth_enabled_cached_until: float = 0.0 + + +def invalidate_auth_enabled_cache() -> None: + """Drop the cached auth-enabled flag so the next probe re-reads the DB. + + Call after any write that toggles the ``auth_enabled`` setting. + """ + global _auth_enabled_cached_value, _auth_enabled_cached_until + _auth_enabled_cached_value = False + _auth_enabled_cached_until = 0.0 + + async def is_auth_enabled(db: AsyncSession) -> bool: """Check if authentication is enabled. @@ -878,12 +919,25 @@ async def is_auth_enabled(db: AsyncSession) -> bool: no exception. Any OTHER failure (connection error, fd exhaustion, schema mismatch, …) propagates so the caller can deny the request (503 / 500). Fail-closed is the only safe default for an auth probe. + + Result is cached briefly to cut per-request DB load on large farms; only + the enabled=True result is cached, so a stale read can only fail closed. + See the module-level cache comment above. """ + global _auth_enabled_cached_value, _auth_enabled_cached_until + if _auth_enabled_cached_value and time.monotonic() < _auth_enabled_cached_until: + return True + result = await db.execute(select(Settings).where(Settings.key == "auth_enabled")) setting = result.scalar_one_or_none() - if setting is None: - return False - return setting.value.lower() == "true" + enabled = setting is not None and setting.value.lower() == "true" + if enabled: + _auth_enabled_cached_value = True + _auth_enabled_cached_until = time.monotonic() + _AUTH_ENABLED_CACHE_TTL_SECONDS + else: + # Never cache "disabled" — keep failing closed on any future staleness. + _auth_enabled_cached_value = False + return enabled async def _user_from_api_key(db: AsyncSession, api_key: APIKey) -> User | None: @@ -973,13 +1027,16 @@ async def get_current_user_optional( if username is None: raise _unauthorized jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): - raise _unauthorized # I6: revoked token → 401, not anonymous iat: int | float | None = payload.get("iat") except JWTError: raise _unauthorized + if not jti: + raise _unauthorized # I6: revoked token → 401, not anonymous + async with async_session() as db: + if await is_jti_revoked(jti, db): + raise _unauthorized # I6: revoked token → 401, not anonymous user = await get_user_by_username(db, username) if user is None or not user.is_active: raise _unauthorized @@ -1006,13 +1063,16 @@ async def get_current_user( if username is None: raise credentials_exception jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): - raise credentials_exception iat: int | float | None = payload.get("iat") except JWTError: raise credentials_exception + if not jti: + raise credentials_exception + async with async_session() as db: + if await is_jti_revoked(jti, db): + raise credentials_exception user = await get_user_by_username(db, username) if user is None: raise credentials_exception @@ -1082,7 +1142,7 @@ async def require_auth_if_enabled( headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", @@ -1191,7 +1251,7 @@ def require_admin_if_auth_enabled(): headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", @@ -1431,7 +1491,7 @@ def require_permission(*permissions: str | Permission): if username is None: raise credentials_exception jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise credentials_exception iat: int | float | None = payload.get("iat") except JWTError: @@ -1518,7 +1578,7 @@ def require_permission_if_auth_enabled(*permissions: str | Permission): headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", @@ -1618,7 +1678,7 @@ def require_any_permission_if_auth_enabled(*permissions: str | Permission): headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", @@ -1795,7 +1855,7 @@ def require_ownership_permission( headers={"WWW-Authenticate": "Bearer"}, ) jti: str | None = payload.get("jti") - if not jti or await is_jti_revoked(jti): + if not jti or await is_jti_revoked(jti, db): raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Could not validate credentials", diff --git a/backend/app/core/config.py b/backend/app/core/config.py index eb29f6f83..1a50a7b3d 100644 --- a/backend/app/core/config.py +++ b/backend/app/core/config.py @@ -74,6 +74,17 @@ class Settings(BaseSettings): log_dir: Path = _log_dir database_url: str = _external_db_url or f"sqlite+aiosqlite:///{_db_path}" + # Database connection pool sizing. ``None`` = use the built-in, dialect-aware + # default (PostgreSQL: pool_size 20 + max_overflow 80; SQLite: 20 + 200). + # Large PostgreSQL printer farms can raise these via the DB_POOL_SIZE / + # DB_MAX_OVERFLOW / DB_POOL_TIMEOUT / DB_POOL_RECYCLE env vars (issue #2572). + # Make sure PostgreSQL ``max_connections`` comfortably exceeds + # (pool_size + max_overflow) x number of app worker processes. + db_pool_size: int | None = Field(default=None, gt=0) + db_max_overflow: int | None = Field(default=None, ge=0) + db_pool_timeout: int | None = Field(default=None, gt=0) + db_pool_recycle: int | None = Field(default=None, gt=0) + # Logging log_level: str = "INFO" # Override with LOG_LEVEL env var or DEBUG=true log_to_file: bool = True # Set to false to disable file logging diff --git a/backend/app/core/database.py b/backend/app/core/database.py index 8e8b36c67..591e966f8 100644 --- a/backend/app/core/database.py +++ b/backend/app/core/database.py @@ -23,12 +23,54 @@ def _set_sqlite_pragmas(dbapi_conn, connection_record): cursor.close() +# Resolved connection-pool configuration, captured at engine creation so +# /system/db-pool can report it without re-deriving the dialect defaults. +_pool_config: dict = {} + + +def _resolve_pool_kwargs() -> dict: + """Build the pool kwargs for ``create_async_engine`` (issue #2572). + + Dialect-aware defaults, each overridable via env (``DB_POOL_SIZE`` etc.): + - PostgreSQL: pool_size 20 + max_overflow 80, ``pool_pre_ping`` (recover + server-dropped connections instead of erroring the request) and + ``pool_recycle`` 1800s. The old hard-coded 10 + 20 exhausted on large + farms while printer callbacks held connections. + - SQLite: pool_size 20 + max_overflow 200 (unchanged); no pre-ping / + recycle — the connection is a local file, not a server socket. + """ + if is_sqlite(): + pool_size = settings.db_pool_size if settings.db_pool_size is not None else 20 + max_overflow = settings.db_max_overflow if settings.db_max_overflow is not None else 200 + kwargs = {"pool_size": pool_size, "max_overflow": max_overflow} + else: + pool_size = settings.db_pool_size if settings.db_pool_size is not None else 20 + max_overflow = settings.db_max_overflow if settings.db_max_overflow is not None else 80 + kwargs = { + "pool_size": pool_size, + "max_overflow": max_overflow, + "pool_pre_ping": True, + "pool_recycle": settings.db_pool_recycle if settings.db_pool_recycle is not None else 1800, + } + if settings.db_pool_timeout is not None: + kwargs["pool_timeout"] = settings.db_pool_timeout + return kwargs + + def _create_engine(): """Create the async engine with dialect-appropriate settings.""" - if is_sqlite(): - kwargs = {"pool_size": 20, "max_overflow": 200} - else: - kwargs = {"pool_size": 10, "max_overflow": 20} + kwargs = _resolve_pool_kwargs() + + global _pool_config + _pool_config = { + "pool_size": kwargs["pool_size"], + "max_overflow": kwargs["max_overflow"], + # SQLAlchemy's own defaults when we don't pass the kwarg. + "pool_timeout": kwargs.get("pool_timeout", 30), + "pool_recycle": kwargs.get("pool_recycle", -1), + "pool_pre_ping": kwargs.get("pool_pre_ping", False), + } + eng = create_async_engine( settings.database_url, echo=settings.debug, @@ -79,6 +121,36 @@ async_session = async_sessionmaker( ) +def get_pool_status() -> dict: + """Snapshot the DB connection pool for diagnostics (issue #2572). + + Returns the resolved configuration plus live gauges (checked-out / + checked-in / overflow). Reads the pool's own counters — it does NOT + check out a connection, so it stays truthful even when the pool is + exhausted. Gauges a given pool implementation doesn't expose come back + as ``None`` rather than raising. + """ + pool = engine.sync_engine.pool + gauges: dict = {} + for key, method_name in ( + ("current_size", "size"), + ("checked_out", "checkedout"), + ("checked_in", "checkedin"), + ("overflow", "overflow"), + ): + method = getattr(pool, method_name, None) + try: + gauges[key] = method() if callable(method) else None + except Exception: + # A gauge should never take down the diagnostics endpoint. + gauges[key] = None + return { + "dialect": "sqlite" if is_sqlite() else "postgresql", + "config": dict(_pool_config), + **gauges, + } + + async def run_with_retry(fn, *, max_attempts: int = 3, label: str = ""): """Run an async DB operation with retry for SQLite 'database is locked' errors. diff --git a/backend/app/main.py b/backend/app/main.py index 112822e7c..e79bd0264 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -6824,16 +6824,16 @@ async def auth_middleware(request, call_next): raise ValueError("No jti in token") iat = payload.get("iat") - # Reject revoked tokens (defense-in-depth gateway check) - if await is_jti_revoked(jti): - return JSONResponse( - status_code=401, - content={"detail": "Token has been revoked"}, - headers={"WWW-Authenticate": "Bearer"}, - ) - - # Verify user exists, is active, and token is still fresh (L-R8-A) + # Verify user exists, is active, and token is still fresh (L-R8-A). + # Reject revoked tokens first (defense-in-depth gateway check), reusing + # this session so the gateway adds a single pooled checkout, not two (#2572). async with async_session() as db: + if await is_jti_revoked(jti, db): + return JSONResponse( + status_code=401, + content={"detail": "Token has been revoked"}, + headers={"WWW-Authenticate": "Bearer"}, + ) user = await get_user_by_username(db, username) if not user or not user.is_active: return JSONResponse( diff --git a/backend/tests/conftest.py b/backend/tests/conftest.py index 8068894ff..fdbe90562 100644 --- a/backend/tests/conftest.py +++ b/backend/tests/conftest.py @@ -95,6 +95,22 @@ def reset_spoolman_location_sync_cache(): _spoolman_location_sync_cache_clear() +@pytest.fixture(autouse=True) +def reset_auth_enabled_cache(): + """Drop the module-level auth-enabled cache between tests (issue #2572). + + ``is_auth_enabled`` caches an enabled=True result for a TTL. Without this + reset a test that enables auth would leave ``True`` cached, so a later test + running in auth-disabled mode (without going through ``set_auth_enabled``) + would wrongly see auth as enabled until the TTL expired — order-dependent + flakiness.""" + from backend.app.core.auth import invalidate_auth_enabled_cache + + invalidate_auth_enabled_cache() + yield + invalidate_auth_enabled_cache() + + @pytest.fixture(scope="session") def event_loop(): """Create an instance of the default event loop for each test session.""" diff --git a/backend/tests/unit/test_db_pool_and_auth_cache.py b/backend/tests/unit/test_db_pool_and_auth_cache.py new file mode 100644 index 000000000..f55b41701 --- /dev/null +++ b/backend/tests/unit/test_db_pool_and_auth_cache.py @@ -0,0 +1,191 @@ +"""Tests for the DB connection-pool sizing/diagnostics and the auth-enabled +cache added for large printer farms (issue #2572).""" + +import asyncio + +import pytest +from sqlalchemy import text +from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine + + +class TestPoolConfiguration: + """P0: env-configurable, dialect-aware pool sizing.""" + + def test_sqlite_defaults_when_unset(self, monkeypatch): + """SQLite keeps 20 + 200 when no env override is set.""" + from backend.app.core import database + + for attr in ("db_pool_size", "db_max_overflow", "db_pool_timeout", "db_pool_recycle"): + monkeypatch.setattr(database.settings, attr, None, raising=False) + monkeypatch.setattr(database, "is_sqlite", lambda: True) + + kwargs = database._resolve_pool_kwargs() + assert kwargs["pool_size"] == 20 + assert kwargs["max_overflow"] == 200 + # No server-socket recycle/pre-ping for a local file. + assert "pool_pre_ping" not in kwargs + assert "pool_recycle" not in kwargs + + def test_postgres_defaults_raise_the_old_limits(self, monkeypatch): + """Postgres default is now 20 + 80 (was 10 + 20) with pre-ping + recycle.""" + from backend.app.core import database + + for attr in ("db_pool_size", "db_max_overflow", "db_pool_timeout", "db_pool_recycle"): + monkeypatch.setattr(database.settings, attr, None, raising=False) + monkeypatch.setattr(database, "is_sqlite", lambda: False) + + kwargs = database._resolve_pool_kwargs() + assert kwargs["pool_size"] == 20 + assert kwargs["max_overflow"] == 80 + assert kwargs["pool_pre_ping"] is True + assert kwargs["pool_recycle"] == 1800 + + def test_env_overrides_win_on_postgres(self, monkeypatch): + """DB_POOL_* overrides replace the dialect defaults.""" + from backend.app.core import database + + monkeypatch.setattr(database.settings, "db_pool_size", 100, raising=False) + monkeypatch.setattr(database.settings, "db_max_overflow", 200, raising=False) + monkeypatch.setattr(database.settings, "db_pool_timeout", 45, raising=False) + monkeypatch.setattr(database.settings, "db_pool_recycle", 600, raising=False) + monkeypatch.setattr(database, "is_sqlite", lambda: False) + + kwargs = database._resolve_pool_kwargs() + assert kwargs["pool_size"] == 100 + assert kwargs["max_overflow"] == 200 + assert kwargs["pool_timeout"] == 45 + assert kwargs["pool_recycle"] == 600 + + @pytest.mark.asyncio + async def test_concurrent_checkouts_exceed_base_pool_size(self, tmp_path): + """Regression (#2572): more concurrent sessions than pool_size must all + complete by drawing from max_overflow — not deadlock or time out. + + This is the failure the farm hit: printer callbacks held every base + connection, so unrelated requests waited on the pool. With headroom in + max_overflow, concurrent checkouts beyond pool_size still succeed. + + Uses a file-based SQLite URL so it gets a real queue pool — the + in-memory URL forces a single-connection StaticPool that ignores + pool_size/max_overflow entirely. + """ + db_file = tmp_path / "pool_regression.db" + eng = create_async_engine(f"sqlite+aiosqlite:///{db_file}", pool_size=2, max_overflow=10) + sm = async_sessionmaker(eng) + + async def _one(): + async with sm() as s: + await s.execute(text("SELECT 1")) + # Hold the checkout briefly so the calls genuinely overlap and + # force the pool past its base size of 2. + await asyncio.sleep(0.05) + return (await s.execute(text("SELECT 1"))).scalar() + + try: + results = await asyncio.gather(*[_one() for _ in range(12)]) + finally: + await eng.dispose() + + assert results == [1] * 12 + + +class TestPoolStatus: + """P3: diagnostics snapshot.""" + + def test_get_pool_status_shape(self): + from backend.app.core.database import get_pool_status + + status = get_pool_status() + assert status["dialect"] in ("sqlite", "postgresql") + for key in ("pool_size", "max_overflow", "pool_timeout", "pool_recycle", "pool_pre_ping"): + assert key in status["config"] + # Live gauges are present (values are ints on a QueuePool). + for key in ("current_size", "checked_out", "checked_in", "overflow"): + assert key in status + + +class TestAuthEnabledCache: + """P1: cache the auth-enabled probe, but only ever cache True.""" + + class _Setting: + def __init__(self, value): + self.value = value + + class _Result: + def __init__(self, setting): + self._setting = setting + + def scalar_one_or_none(self): + return self._setting + + class _CountingDB: + def __init__(self, value): + self._value = value + self.calls = 0 + + async def execute(self, *args, **kwargs): + self.calls += 1 + setting = None if self._value is None else TestAuthEnabledCache._Setting(self._value) + return TestAuthEnabledCache._Result(setting) + + @pytest.mark.asyncio + async def test_enabled_true_is_cached(self): + from backend.app.core import auth as auth_mod + + auth_mod.invalidate_auth_enabled_cache() + db = self._CountingDB("true") + + assert await auth_mod.is_auth_enabled(db) is True + assert db.calls == 1 + # Second probe served from cache — no new query. + assert await auth_mod.is_auth_enabled(db) is True + assert db.calls == 1 + + # Invalidation forces a re-read (e.g. after set_auth_enabled). + auth_mod.invalidate_auth_enabled_cache() + assert await auth_mod.is_auth_enabled(db) is True + assert db.calls == 2 + auth_mod.invalidate_auth_enabled_cache() + + @pytest.mark.asyncio + async def test_disabled_is_never_cached(self): + """SECURITY: a disabled result must never be cached, so staleness can + only ever fail closed (require auth), never open.""" + from backend.app.core import auth as auth_mod + + auth_mod.invalidate_auth_enabled_cache() + db = self._CountingDB("false") + + assert await auth_mod.is_auth_enabled(db) is False + assert db.calls == 1 + # Every probe re-reads while disabled. + assert await auth_mod.is_auth_enabled(db) is False + assert db.calls == 2 + auth_mod.invalidate_auth_enabled_cache() + + @pytest.mark.asyncio + async def test_unconfigured_returns_false_and_is_not_cached(self): + from backend.app.core import auth as auth_mod + + auth_mod.invalidate_auth_enabled_cache() + db = self._CountingDB(None) + + assert await auth_mod.is_auth_enabled(db) is False + assert await auth_mod.is_auth_enabled(db) is False + assert db.calls == 2 + auth_mod.invalidate_auth_enabled_cache() + + @pytest.mark.asyncio + async def test_db_error_propagates_fail_closed(self): + """A probe error must propagate (fail closed), not be swallowed.""" + from backend.app.core import auth as auth_mod + + auth_mod.invalidate_auth_enabled_cache() + + class _RaisingDB: + async def execute(self, *args, **kwargs): + raise RuntimeError("connection lost") + + with pytest.raises(RuntimeError): + await auth_mod.is_auth_enabled(_RaisingDB()) + auth_mod.invalidate_auth_enabled_cache() diff --git a/backend/tests/unit/test_jti_revoked_session_reuse_2572.py b/backend/tests/unit/test_jti_revoked_session_reuse_2572.py new file mode 100644 index 000000000..9ba415cd7 --- /dev/null +++ b/backend/tests/unit/test_jti_revoked_session_reuse_2572.py @@ -0,0 +1,83 @@ +"""``is_jti_revoked`` must reuse the caller's session when given one (#2572). + +The permission dependencies already hold a DB session when they check whether +a JWT's ``jti`` is revoked. The old ``is_jti_revoked`` always opened a *second* +``async_session``, so every authenticated request checked out two pooled +connections instead of one. On a large farm a burst of concurrent logins then +exhausted the pool (reporter @Jostxxl). Passing the existing session collapses +each request back to a single checkout. + +These tests verify both that the revocation query is still correct and that a +provided session is genuinely reused (no second checkout), while the no-session +call still opens its own — the behaviour older callers rely on. +""" + +from datetime import datetime, timedelta, timezone + +import pytest +from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker + +from backend.app.core import auth as auth_mod +from backend.app.core.auth import is_jti_revoked +from backend.app.models.auth_ephemeral import AuthEphemeralToken + + +def _revoked_row(token: str) -> AuthEphemeralToken: + return AuthEphemeralToken( + token=token, + token_type="revoked_jti", + expires_at=datetime.now(timezone.utc) + timedelta(hours=1), + ) + + +@pytest.mark.asyncio +async def test_revoked_jti_detected_via_provided_session(db_session): + """A revoked jti is reported revoked when the caller passes its session.""" + db_session.add(_revoked_row("jti-revoked-1")) + await db_session.commit() + + assert await is_jti_revoked("jti-revoked-1", db_session) is True + + +@pytest.mark.asyncio +async def test_unknown_jti_not_revoked_via_provided_session(db_session): + assert await is_jti_revoked("jti-never-seen", db_session) is False + + +@pytest.mark.asyncio +async def test_provided_session_is_reused_not_a_second_checkout(db_session, monkeypatch): + """PERF regression (#2572): passing ``db`` must NOT open a new session — + that second checkout per request is the pool pressure we removed.""" + opened = {"n": 0} + original = auth_mod.async_session + + def _counting(*args, **kwargs): + opened["n"] += 1 + return original(*args, **kwargs) + + monkeypatch.setattr(auth_mod, "async_session", _counting) + + assert await is_jti_revoked("jti-with-session", db_session) is False + assert opened["n"] == 0, "is_jti_revoked opened its own session despite being given one" + + +@pytest.mark.asyncio +async def test_no_session_still_opens_its_own(test_engine, monkeypatch): + """Callers that check the jti before they have a session (e.g. the token + dependencies) must keep working — omitting ``db`` opens a short one.""" + test_async_session = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False) + + async with test_async_session() as seed: + seed.add(_revoked_row("jti-revoked-2")) + await seed.commit() + + opened = {"n": 0} + + def _counting(*args, **kwargs): + opened["n"] += 1 + return test_async_session(*args, **kwargs) + + monkeypatch.setattr(auth_mod, "async_session", _counting) + + assert await is_jti_revoked("jti-revoked-2") is True + assert opened["n"] == 1, "is_jti_revoked should open exactly one session when none is provided"