fix(auth): a database error while checking an API key is a 503, not an invalid key

CHANGELOG.md

@@ -161,6 +161,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows.
 
 ### Fixed
+- **A valid API key could be refused as invalid during a brief database problem** — When checking an API key hit a database error (a busy database, or saving the key's last-used time while it was locked), the request was answered "Invalid API key", so integrations such as Home Assistant or scripts were told their key was wrong. It now answers "Authentication service temporarily unavailable" (503), which a client can retry, and the error is logged. A wrong or expired key is refused as before.
 - **Errors were reported as "Authentication service temporarily unavailable" with login switched off** — Without authentication, any unexpected error in Bambuddy answered 503 "Authentication service temporarily unavailable", and the log blamed the authentication check, which sent troubleshooting the wrong way. Such errors are now reported as the internal error they are (500), and the error with its details now lands in `bambuddy.log` (and so in support packages), whether login is on or off. The protection that refuses requests when Bambuddy can't tell whether login is on stays as it was.
   - **With login on, a brief database hiccup no longer signs you out:** while checking a sign-in, a database error answered "Invalid token", and the web interface took that as final, signed the user out and forgot the sign-in. It now answers "Authentication service temporarily unavailable", which the interface retries, and the error is logged.
 - **A print started outside Bambuddy could be reported to the owner of the previous queue job** — On a printer with **Auto-archive completed prints** switched off (in the printer's settings), a print Bambuddy didn't start (for example one started on the printer itself) has no archive. When it finished, failed or was stopped, the notification looked for any queue job this printer had finished in the last five minutes and treated the print as that job: its owner got the "your print is done" email for a print that wasn't theirs. It now uses only the queue job the print itself belongs to, so such a print isn't sent to anyone's personal email.

backend/app/core/auth.py

@@ -14,6 +14,7 @@ from fastapi import Depends, Header, HTTPException, status
 from fastapi.security import HTTPAuthorizationCredentials, HTTPBearer
 from jwt.exceptions import PyJWTError as JWTError
 from passlib.context import CryptContext
+from passlib.exc import PasswordSizeError
 from sqlalchemy import delete, func, select
 from sqlalchemy.ext.asyncio import AsyncSession
 from sqlalchemy.orm import selectinload
@@ -1402,18 +1403,35 @@ _validated_api_key: ContextVar[tuple[str, APIKey] | None] = ContextVar("_validat
 _authenticated_user: ContextVar[tuple[str, User] | None] = ContextVar("_authenticated_user", default=None)
 
 
+def _api_key_check_unavailable(error: Exception) -> HTTPException:
+    """The 503 for a key that couldn't be checked (database, pool), logged.
+
+    Not 401: the key may well be valid, and clients treat 401 "Invalid API key"
+    as final (the web interface clears its sign-in on it). Still fail-closed:
+    the request is refused either way.
+    """
+    logger.error("API key check failed: %s", error, exc_info=error)
+    return HTTPException(
+        status_code=status.HTTP_503_SERVICE_UNAVAILABLE,
+        detail="Authentication service temporarily unavailable",
+    )
+
+
 async def _validate_api_key(db: AsyncSession, api_key_value: str) -> APIKey | None:
     """Validate an API key and return the APIKey object if valid, None otherwise.
 
+    Raises a 503 HTTPException when the key can't be checked at all (database
+    or pool error): that is not an invalid key, and must not read as one.
+
     L-1: Pre-filter by key_prefix (first 8 chars) before running pbkdf2 so only
     O(1) candidate rows are hashed instead of the full key table.  The prefix is
     not secret (it is shown in the admin UI), so this does not reduce security.
     """
+    # key_prefix is stored as "<first-8-chars>..." (e.g. "bb_Abc12...").
+    # Matching on the first 8 chars of the submitted key reduces the scan to
+    # at most one row in practice (2^40 collision space for 5 base64 chars).
+    key_lookup = api_key_value[:8] if len(api_key_value) >= 8 else api_key_value
     try:
-        # key_prefix is stored as "<first-8-chars>..." (e.g. "bb_Abc12...").
-        # Matching on the first 8 chars of the submitted key reduces the scan to
-        # at most one row in practice (2^40 collision space for 5 base64 chars).
-        key_lookup = api_key_value[:8] if len(api_key_value) >= 8 else api_key_value
         result = await db.execute(
             select(APIKey).where(
                 APIKey.enabled.is_(True),
@@ -1423,23 +1441,38 @@ async def _validate_api_key(db: AsyncSession, api_key_value: str) -> APIKey | No
             )
         )
         api_keys = result.scalars().all()
+    except Exception as e:  # SEC-AUTH-EXC: key lookup failed -> raises 503, request refused (no key returned)
+        raise _api_key_check_unavailable(e) from e
 
-        for api_key in api_keys:
-            if verify_password(api_key_value, api_key.key_hash):
-                # Check expiration
-                if api_key.expires_at:
-                    expires = api_key.expires_at
-                    if expires.tzinfo is None:
-                        expires = expires.replace(tzinfo=timezone.utc)
-                    if expires < datetime.now(timezone.utc):
-                        return None  # Expired
-                # Update last_used timestamp
-                api_key.last_used = datetime.now(timezone.utc)
-                await db.commit()
-                _validated_api_key.set((api_key_value, api_key))
-                return api_key
-    except Exception as e:  # SEC-AUTH-EXC: validation failure returns None; every caller treats None as "invalid key" → 401 (fail-closed)
-        logger.warning("API key validation error: %s", e)
+    for api_key in api_keys:
+        try:
+            matches = verify_password(api_key_value, api_key.key_hash)
+        except PasswordSizeError:
+            # The submitted value is too long to hash (passlib's limit): the
+            # client's input, not this row, and certainly not a match.
+            continue
+        except Exception as e:  # SEC-AUTH-EXC: unverifiable hash counts as no match -> None -> 401
+            # An unreadable stored hash can't vouch for anything: not a match.
+            logger.warning("API key %s has an unreadable hash: %s", api_key.id, e)
+            continue
+        if not matches:
+            continue
+        # Check expiration
+        if api_key.expires_at:
+            expires = api_key.expires_at
+            if expires.tzinfo is None:
+                expires = expires.replace(tzinfo=timezone.utc)
+            if expires < datetime.now(timezone.utc):
+                return None  # Expired
+        # Update last_used timestamp
+        api_key.last_used = datetime.now(timezone.utc)
+        try:
+            await db.commit()
+        except Exception as e:  # SEC-AUTH-EXC: last_used write failed -> rollback + raise 503, key not returned
+            await db.rollback()
+            raise _api_key_check_unavailable(e) from e
+        _validated_api_key.set((api_key_value, api_key))
+        return api_key
     return None
 
 

backend/tests/integration/test_api_key_infra_errors.py

@@ -0,0 +1,150 @@
+"""A database error while checking an API key is not an invalid key.
+
+``_validate_api_key`` caught every exception and returned None, which every
+caller answers with 401 "Invalid API key": a valid key was refused as wrong
+during a pool timeout, or when writing its last-used time hit "database is
+locked", and the web interface clears its sign-in on that message. Such an
+error now refuses the request with 503, as the auth checks in the middleware
+do, and is logged.
+"""
+
+import logging
+from contextlib import contextmanager
+from datetime import datetime, timedelta, timezone
+
+import pytest
+from sqlalchemy import event, update
+from sqlalchemy.exc import OperationalError
+
+from backend.app.models.api_key import APIKey
+
+
+async def _admin_headers(async_client) -> dict[str, str]:
+    await async_client.post(
+        "/api/v1/auth/setup",
+        json={"auth_enabled": True, "admin_username": "keyadmin", "admin_password": "AdminPass1!"},
+    )
+    login = await async_client.post("/api/v1/auth/login", json={"username": "keyadmin", "password": "AdminPass1!"})
+    assert login.status_code == 200, login.text
+    return {"Authorization": f"Bearer {login.json()['access_token']}"}
+
+
+async def _key(async_client) -> str:
+    admin = await _admin_headers(async_client)
+    created = await async_client.post(
+        "/api/v1/api-keys/", headers=admin, json={"name": "integration", "can_read_status": True}
+    )
+    assert created.status_code in (200, 201), created.text
+    return created.json()["key"]
+
+
+@contextmanager
+def _failing(test_engine, statement_start: str):
+    """Make the next statement starting with *statement_start* fail as SQLite does when locked."""
+    state = {"failed": False}
+
+    def hook(conn, cursor, statement, parameters, context, executemany):
+        if not state["failed"] and statement.lstrip().upper().startswith(statement_start):
+            state["failed"] = True
+            raise OperationalError(statement, parameters, Exception("database is locked"))
+
+    event.listen(test_engine.sync_engine, "before_cursor_execute", hook)
+    try:
+        yield state
+    finally:
+        event.remove(test_engine.sync_engine, "before_cursor_execute", hook)
+
+
+PROTECTED = "/api/v1/printers/"
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_valid_key_works(async_client):
+    key = await _key(async_client)
+
+    response = await async_client.get(PROTECTED, headers={"X-API-Key": key})
+
+    assert response.status_code == 200, response.text
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_failed_key_lookup_is_a_logged_503(async_client, test_engine, caplog):
+    key = await _key(async_client)
+
+    with _failing(test_engine, "SELECT API_KEYS") as state, caplog.at_level(logging.ERROR):
+        response = await async_client.get(PROTECTED, headers={"X-API-Key": key})
+
+    assert state["failed"]
+    assert response.status_code == 503, response.text
+    assert response.json()["detail"] == "Authentication service temporarily unavailable"
+    assert "database is locked" in caplog.text
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_failed_last_used_write_is_a_503_not_an_invalid_key(async_client, test_engine):
+    key = await _key(async_client)
+
+    with _failing(test_engine, "UPDATE API_KEYS") as state:
+        response = await async_client.get(PROTECTED, headers={"X-API-Key": key})
+
+    assert state["failed"]
+    assert response.status_code == 503, response.text
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_wrong_key_is_still_a_401(async_client):
+    key = await _key(async_client)
+
+    response = await async_client.get(PROTECTED, headers={"X-API-Key": key[:-4] + "XXXX"})
+
+    # The message depends on the route's dependency ("Invalid API key" or
+    # "Authentication required"); the refusal is what matters.
+    assert response.status_code == 401
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_an_expired_key_is_still_a_401(async_client, db_session):
+    key = await _key(async_client)
+    await db_session.execute(
+        update(APIKey)
+        .values(expires_at=datetime.now(timezone.utc) - timedelta(days=1))
+        .where(APIKey.name == "integration")
+    )
+    await db_session.commit()
+
+    response = await async_client.get(PROTECTED, headers={"X-API-Key": key})
+
+    assert response.status_code == 401
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_key_row_with_an_unreadable_hash_is_no_match_and_is_reported(async_client, db_session, caplog):
+    key = await _key(async_client)
+    await db_session.execute(update(APIKey).values(key_hash="not-a-hash").where(APIKey.name == "integration"))
+    await db_session.commit()
+
+    with caplog.at_level(logging.WARNING):
+        response = await async_client.get(PROTECTED, headers={"X-API-Key": key})
+
+    assert response.status_code == 401
+    assert "unreadable hash" in caplog.text
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_an_oversized_key_is_refused_without_blaming_the_stored_hash(async_client, caplog):
+    """passlib refuses secrets over 4096 characters; that is the client's input,
+    not a broken row, and must not be logged as one."""
+    key = await _key(async_client)
+
+    with caplog.at_level(logging.WARNING):
+        response = await async_client.get(PROTECTED, headers={"X-API-Key": key[:8] + "a" * 5000})
+
+    assert response.status_code == 401
+    assert "unreadable hash" not in caplog.text