fix(auth): route errors are 500s and reach bambuddy.log, and a database error no longer signs users out

CHANGELOG.md

@@ -161,6 +161,8 @@ 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
+- **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.
   - **A queue job whose archive couldn't be found** at the end, when it finishes or fails, is still reported to its owner, and its duration (`{duration}`) is how long it actually ran instead of "Unknown". A job stopped from the queue page in that situation no longer sends its owner the "stopped" email.
 - **Smart plug power alerts were never sent** — A plug's **Power Alerts** (alert if the power is above or below a value) never reached any notification provider, and each time one was due, that request for the plug's status on the printer card failed. They also were only checked while someone had a printer page open.

backend/app/main.py

@@ -328,6 +328,19 @@ console_handler.setFormatter(logging.Formatter(log_format))
 console_handler.addFilter(_trace_id_filter)
 root_logger.addHandler(console_handler)
 
+
+def _attach_file_handler_to_uvicorn(handler: logging.Handler) -> None:
+    """Send uvicorn's own loggers to bambuddy.log as well.
+
+    Both ship with propagate=False, so the root handler never sees them.
+    uvicorn.access is the record of which endpoint changed server state;
+    uvicorn.error is where an unhandled route error is logged with its
+    traceback ("Exception in ASGI application").
+    """
+    for name in ("uvicorn.access", "uvicorn.error"):
+        logging.getLogger(name).addHandler(handler)
+
+
 # File handler - only in production or if explicitly enabled
 if app_settings.log_to_file:
     log_file = app_settings.log_dir / "bambuddy.log"
@@ -355,8 +368,8 @@ if app_settings.log_to_file:
         WriteRequestsOnlyFilter,
     )
 
+    _attach_file_handler_to_uvicorn(file_handler)
     uvicorn_access_logger = logging.getLogger("uvicorn.access")
-    uvicorn_access_logger.addHandler(file_handler)
     uvicorn_access_logger.addFilter(WriteRequestsOnlyFilter())
     # Uvicorn's access logger has propagate=False (its own default), so the
     # root-attached TraceIDFilter never sees these records. Attach a
@@ -10810,15 +10823,13 @@ async def auth_middleware(request, call_next):
     # probe — GHSA-6mf4-q26m-47pv: the previous fail-open path here let
     # an attacker who could force a DB exception (e.g. file-descriptor
     # exhaustion via login flood) bypass auth on every protected endpoint.
+    # Only the probe is guarded: the request itself runs outside the try, so an
+    # error in a route surfaces as the 500 it is rather than as an auth outage.
     try:
         async with async_session() as db:
             from backend.app.core.auth import is_auth_enabled
 
             auth_enabled = await is_auth_enabled(db)
-
-        if not auth_enabled:
-            # Auth disabled, allow all requests
-            return await call_next(request)
     except Exception:
         logging.getLogger(__name__).exception("auth_middleware: failing closed on auth-probe error from %s", path)
         return JSONResponse(
@@ -10826,6 +10837,10 @@ async def auth_middleware(request, call_next):
             content={"detail": "Authentication service temporarily unavailable"},
         )
 
+    if not auth_enabled:
+        # Auth disabled, allow all requests
+        return await call_next(request)
+
     # Auth is enabled - require valid token
     auth_header = request.headers.get("Authorization")
     x_api_key = request.headers.get("X-API-Key")
@@ -10895,12 +10910,21 @@ async def auth_middleware(request, call_next):
             content={"detail": "Token has expired"},
             headers={"WWW-Authenticate": "Bearer"},
         )
-    except (jwt.InvalidTokenError, ValueError, Exception):
+    except (jwt.InvalidTokenError, ValueError):
         return JSONResponse(
             status_code=401,
             content={"detail": "Invalid token"},
             headers={"WWW-Authenticate": "Bearer"},
         )
+    except Exception:
+        # Not a bad token but a failure checking it (database, pool): refuse,
+        # as for the probe above, rather than answer 401 -- the frontend reads
+        # a 401 from /auth/me as final and signs the user out.
+        logging.getLogger(__name__).exception("auth_middleware: failing closed on token-check error from %s", path)
+        return JSONResponse(
+            status_code=503,
+            content={"detail": "Authentication service temporarily unavailable"},
+        )
 
     return await call_next(request)
 

backend/tests/integration/test_auth_middleware_errors.py

@@ -0,0 +1,203 @@
+"""The auth middleware fails closed on its own probe, and only there.
+
+The middleware asks the database whether authentication is on. If that probe
+fails it must answer 503 and never fall through to "auth off" (the fail-open
+bypass the probe used to have). Pre-fix the request itself also ran inside that
+``try``, so with authentication off any error in any route was answered 503
+"Authentication service temporarily unavailable" and logged as an auth-probe
+failure, instead of surfacing as the 500 it is.
+"""
+
+import logging
+from collections.abc import AsyncIterator
+from unittest.mock import AsyncMock, patch
+
+import pytest
+from fastapi.routing import APIRoute
+from httpx import ASGITransport, AsyncClient
+
+from backend.app.main import app
+
+PROBE_PATH = "/api/v1/__test_auth_middleware"
+
+
+@pytest.fixture
+async def client(async_client) -> AsyncIterator[AsyncClient]:
+    """A client that receives the 500 instead of re-raising it, and a test route.
+
+    Depends on async_client for the test database wiring it sets up.
+    """
+    calls = {"n": 0}
+
+    async def route(crash: bool = False):
+        calls["n"] += 1
+        if crash:
+            raise RuntimeError("route failed")
+        return {"ok": True}
+
+    # In front of everything else: the SPA's catch-all route would match first.
+    app.router.routes.insert(0, APIRoute(PROBE_PATH, route, methods=["GET"]))
+    try:
+        async with AsyncClient(
+            transport=ASGITransport(app=app, raise_app_exceptions=False), base_url="http://test"
+        ) as c:
+            c.calls = calls  # type: ignore[attr-defined]
+            yield c
+    finally:
+        app.router.routes[:] = [r for r in app.router.routes if getattr(r, "path", None) != PROBE_PATH]
+
+
+class TestFailsClosedOnTheProbe:
+    @pytest.mark.asyncio
+    async def test_a_failing_probe_answers_503_and_never_reaches_the_route(self, client):
+        with patch("backend.app.core.auth.is_auth_enabled", AsyncMock(side_effect=OSError("too many open files"))):
+            response = await client.get(PROBE_PATH)
+
+        assert response.status_code == 503
+        assert response.json() == {"detail": "Authentication service temporarily unavailable"}
+        assert client.calls["n"] == 0
+
+
+class TestRouteErrorsAreNotAuthErrors:
+    @pytest.mark.asyncio
+    async def test_with_auth_off_a_route_error_is_a_500(self, client, caplog):
+        with (
+            patch("backend.app.core.auth.is_auth_enabled", AsyncMock(return_value=False)),
+            caplog.at_level(logging.ERROR),
+        ):
+            response = await client.get(PROBE_PATH, params={"crash": "true"})
+
+        assert response.status_code == 500
+        assert "Authentication service" not in response.text
+        assert "auth-probe" not in caplog.text
+        assert client.calls["n"] == 1
+
+    @pytest.mark.asyncio
+    async def test_with_auth_off_a_working_route_still_answers(self, client):
+        with patch("backend.app.core.auth.is_auth_enabled", AsyncMock(return_value=False)):
+            response = await client.get(PROBE_PATH)
+
+        assert response.status_code == 200
+        assert response.json() == {"ok": True}
+
+    @pytest.mark.asyncio
+    async def test_with_auth_on_a_route_error_is_a_500(self, client):
+        await client.post(
+            "/api/v1/auth/setup",
+            json={"auth_enabled": True, "admin_username": "mwadmin", "admin_password": "AdminPass1!"},
+        )
+        login = await client.post("/api/v1/auth/login", json={"username": "mwadmin", "password": "AdminPass1!"})
+        assert login.status_code == 200, login.text
+        headers = {"Authorization": f"Bearer {login.json()['access_token']}"}
+
+        response = await client.get(PROBE_PATH, params={"crash": "true"}, headers=headers)
+
+        assert response.status_code == 500
+        assert "Authentication service" not in response.text
+
+
+class TestRouteErrorsReachTheLogFile:
+    def test_uvicorns_error_log_goes_to_the_log_file_too(self):
+        """An unhandled route error is logged by uvicorn on ``uvicorn.error``.
+
+        Only ``uvicorn.access`` used to get the bambuddy.log handler, so such an
+        error never reached the file a support package is built from.
+        """
+        from backend.app.main import _attach_file_handler_to_uvicorn
+
+        handler = logging.NullHandler()
+        try:
+            _attach_file_handler_to_uvicorn(handler)
+            assert handler in logging.getLogger("uvicorn.error").handlers
+            assert handler in logging.getLogger("uvicorn.access").handlers
+        finally:
+            for name in ("uvicorn.error", "uvicorn.access"):
+                logger = logging.getLogger(name)
+                if handler in logger.handlers:
+                    logger.removeHandler(handler)
+
+    def test_the_app_wires_uvicorns_error_log_to_bambuddy_log(self, tmp_path):
+        """End to end: with file logging on (the default), importing the app
+        attaches bambuddy.log to uvicorn.error, and a record there lands in it."""
+        import os
+        import subprocess
+        import sys
+        from pathlib import Path
+
+        repo = Path(__file__).resolve().parents[3]
+        env = {
+            **os.environ,
+            "LOG_TO_FILE": "true",
+            "LOG_DIR": str(tmp_path),
+            "DATA_DIR": str(tmp_path),
+            "DATABASE_URL": f"sqlite+aiosqlite:///{tmp_path / 'app.db'}",
+            "PYTHONPATH": str(repo),
+        }
+        # uvicorn configures its loggers before it imports the app, and its
+        # config stops uvicorn.error short of the root logger; without that the
+        # record would reach the root's file handler whatever the app does.
+        script = (
+            "import logging, logging.config\n"
+            "from uvicorn.config import LOGGING_CONFIG\n"
+            "logging.config.dictConfig(LOGGING_CONFIG)\n"
+            "import backend.app.main\n"
+            "logging.getLogger('uvicorn.error').error('Exception in ASGI application: marker-7f3a')\n"
+            "for h in logging.getLogger().handlers: h.flush()\n"
+        )
+        result = subprocess.run(
+            [sys.executable, "-c", script], cwd=tmp_path, env=env, capture_output=True, text=True, timeout=120
+        )
+        assert result.returncode == 0, result.stderr[-2000:]
+        assert "marker-7f3a" in (tmp_path / "bambuddy.log").read_text(encoding="utf-8")
+
+
+class TestTokenCheckErrors:
+    """With login on, a database error while checking a token is not a bad token.
+
+    It used to answer 401 "Invalid token", and the frontend treats a 401 from
+    /auth/me as final: it signs the user out and deletes the token. It now
+    fails closed the way the probe does, with a logged 503 the frontend retries.
+    """
+
+    @staticmethod
+    async def _login(client) -> dict[str, str]:
+        await client.post(
+            "/api/v1/auth/setup",
+            json={"auth_enabled": True, "admin_username": "tkadmin", "admin_password": "AdminPass1!"},
+        )
+        login = await client.post("/api/v1/auth/login", json={"username": "tkadmin", "password": "AdminPass1!"})
+        assert login.status_code == 200, login.text
+        return {"Authorization": f"Bearer {login.json()['access_token']}"}
+
+    @pytest.mark.asyncio
+    async def test_a_database_error_is_a_logged_503_not_a_401(self, client, caplog):
+        headers = await self._login(client)
+        with (
+            patch("backend.app.core.auth.is_jti_revoked", AsyncMock(side_effect=OSError("pool timed out"))),
+            caplog.at_level(logging.ERROR),
+        ):
+            response = await client.get(PROBE_PATH, headers=headers)
+
+        assert response.status_code == 503
+        assert response.json() == {"detail": "Authentication service temporarily unavailable"}
+        assert client.calls["n"] == 0
+        assert "pool timed out" in caplog.text
+
+    @pytest.mark.asyncio
+    async def test_a_bad_token_is_still_a_401(self, client):
+        await self._login(client)
+
+        response = await client.get(PROBE_PATH, headers={"Authorization": "Bearer not-a-jwt"})
+
+        assert response.status_code == 401
+        assert response.json() == {"detail": "Invalid token"}
+        assert client.calls["n"] == 0
+
+    @pytest.mark.asyncio
+    async def test_a_valid_token_still_reaches_the_route(self, client):
+        headers = await self._login(client)
+
+        response = await client.get(PROBE_PATH, headers=headers)
+
+        assert response.status_code == 200
+        assert client.calls["n"] == 1

backend/tests/integration/test_inventory_link_tag.py

@@ -8,11 +8,11 @@ when two active spools carry one tag. Nothing prevents that duplicate: no
 unique index, no conflict check on PATCH /spools/{id}, and POST /spools/bulk
 copies one tag into every row it creates.
 
-That exception escapes the route into the auth middleware's fail-closed
-``except Exception`` (main.py:9685), so the caller does not even get a 500 --
-they get 503 "Authentication service temporarily unavailable" for a request
-that has nothing to do with auth. The middleware is right to fail closed
-(GHSA-6mf4-q26m-47pv); the route is what must not raise.
+That exception escaped the route as an unhandled error. (It used to be
+reported as 503 "Authentication service temporarily unavailable", because the
+auth middleware ran the request inside the try that guards its auth probe; the
+middleware now guards only the probe, so such an error is a 500.) Either way
+the route is what must not raise.
 """
 
 from datetime import datetime, timezone