feat: add comprehensive request and error logging

Add logging infrastructure: - RequestLoggingMiddleware: logs all requests with method, path, status, timing - ExceptionLoggingMiddleware: catches and logs unhandled exceptions with stack traces - configure_logging(): structured logging with configurable level via LOG_LEVEL env var Add detailed auth flow logging: - Login initiation - Token exchange success/failure - JWKS fetch success/failure - Token verification - User lookup/creation - Database errors - Final response This enables tracing Internal Server Errors through the logs.
2026-05-18 22:22:56 +02:00
parent c1a4d2d9af
commit 843683d579
3 changed files with 179 additions and 36 deletions
@@ -1,3 +1,4 @@
+import logging
 from secrets import token_urlsafe
 from datetime import UTC, datetime, timedelta
 from typing import AsyncGenerator, Literal, cast
@@ -21,6 +22,8 @@ from src.config import Settings
 from src.database import SessionLocal
 from src.models.user import User

+logger = logging.getLogger(__name__)
+
 router = APIRouter(prefix="/auth", tags=["auth"])


@@ -40,6 +43,7 @@ async def login() -> RedirectResponse:
        state=state,
        nonce=token_urlsafe(16),
    )
+    logger.info("Auth login initiated: redirect_uri=%s", redirect_uri)
    response = RedirectResponse(location)
    response.set_cookie("auth_state", state, httponly=True, samesite="lax")
    return response
@@ -53,55 +57,89 @@ async def callback(
    auth_state: str | None = Cookie(default=None),
    session: AsyncSession = Depends(get_db_session),
 ) -> dict[str, str]:
+    logger.info("Auth callback received: code=%s... state=%s", code[:10] if code else "None", state[:10] if state else "None")
+    
    if auth_state is None or auth_state != state:
+        logger.warning("State mismatch: cookie=%s, param=%s", auth_state, state)
        raise HTTPException(status_code=status.HTTP_401_UNAUTHORIZED, detail="invalid state")

    settings = Settings()
    redirect_uri = f"{settings.api_base_url}/auth/callback"
+    logger.info("Exchanging code for tokens (redirect_uri=%s)", redirect_uri)
+    
    async with httpx.AsyncClient() as client:
-        token_payload = await exchange_code_for_tokens(
-            settings=settings,
-            code=code,
-            redirect_uri=redirect_uri,
-            client=client,
-        )
-        jwks = await fetch_jwks(settings=settings, client=client)
+        try:
+            token_payload = await exchange_code_for_tokens(
+                settings=settings,
+                code=code,
+                redirect_uri=redirect_uri,
+                client=client,
+            )
+            logger.info("Token exchange successful: access_token=%s...", token_payload["access_token"][:20] if token_payload.get("access_token") else "None")
+        except Exception as exc:
+            logger.error("Token exchange failed: %s", exc)
+            raise HTTPException(status_code=status.HTTP_400_BAD_REQUEST, detail=f"token exchange failed: {exc}")
+        
+        try:
+            jwks = await fetch_jwks(settings=settings, client=client)
+            logger.info("JWKS fetched successfully")
+        except Exception as exc:
+            logger.error("JWKS fetch failed: %s", exc)
+            raise HTTPException(status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="failed to fetch JWKS")

-    provider_claims = verify_provider_access_token(
-        settings=settings,
-        token=token_payload["access_token"],
-        jwks=jwks,
-    )
+    try:
+        provider_claims = verify_provider_access_token(
+            settings=settings,
+            token=token_payload["access_token"],
+            jwks=jwks,
+        )
+        logger.info("Token verified successfully for sub=%s", provider_claims.get("sub"))
+    except Exception as exc:
+        logger.error("Token verification failed: %s", exc)
+        raise HTTPException(status_code=status.HTTP_401_UNAUTHORIZED, detail="invalid token")

    authentik_id = str(provider_claims["sub"])
    email = str(provider_claims.get("email", f"{authentik_id}@authentik.local"))
    name = str(provider_claims.get("name", email))
+    logger.info("User info: authentik_id=%s, email=%s, name=%s", authentik_id, email, name)

-    user = await session.scalar(select(User).where(User.authentik_id == authentik_id))
-    if user is None:
-        user = User(email=email, name=name, authentik_id=authentik_id, avatar_url=None)
-        session.add(user)
-        await session.commit()
-        await session.refresh(user)
-    else:
-        user.email = email
-        user.name = name
-        await session.commit()
+    try:
+        user = await session.scalar(select(User).where(User.authentik_id == authentik_id))
+        if user is None:
+            logger.info("Creating new user: authentik_id=%s", authentik_id)
+            user = User(email=email, name=name, authentik_id=authentik_id, avatar_url=None)
+            session.add(user)
+            await session.commit()
+            await session.refresh(user)
+            logger.info("New user created: id=%s", user.id)
+        else:
+            logger.info("Existing user found: id=%s, updating info", user.id)
+            user.email = email
+            user.name = name
+            await session.commit()
+    except Exception as exc:
+        logger.error("Database error during user lookup/creation: %s", exc)
+        raise HTTPException(status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="database error")

-    access_token = mint_access_token(
-        settings=settings,
-        subject=str(user.id),
-        email=user.email,
-        name=user.name,
-        expires_at=datetime.now(UTC) + timedelta(minutes=settings.access_token_ttl_minutes),
-    )
-    refresh_token, _ = await create_refresh_token(
-        session=session,
-        user_id=user.id,
-        expires_at=datetime.now(UTC) + timedelta(days=settings.refresh_token_ttl_days),
-        user_agent=None,
-        ip_address=None,
-    )
+    try:
+        access_token = mint_access_token(
+            settings=settings,
+            subject=str(user.id),
+            email=user.email,
+            name=user.name,
+            expires_at=datetime.now(UTC) + timedelta(minutes=settings.access_token_ttl_minutes),
+        )
+        refresh_token, _ = await create_refresh_token(
+            session=session,
+            user_id=user.id,
+            expires_at=datetime.now(UTC) + timedelta(days=settings.refresh_token_ttl_days),
+            user_agent=None,
+            ip_address=None,
+        )
+        logger.info("Tokens created for user id=%s", user.id)
+    except Exception as exc:
+        logger.error("Token creation failed: %s", exc)
+        raise HTTPException(status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="token creation failed")

    cookie_options = build_cookie_options(settings)
    cookie_samesite = cast(Literal["lax", "strict", "none"], cookie_options["samesite"])
@@ -110,6 +148,7 @@ async def callback(
    response.set_cookie("refresh_token", refresh_token, httponly=True, samesite=cookie_samesite, secure=cookie_secure)
    response.delete_cookie("auth_state", samesite="lax")

+    logger.info("Auth callback complete for user id=%s", user.id)
    return {"sub": str(user.id), "email": user.email, "name": user.name}


@@ -0,0 +1,92 @@
+import logging
+import sys
+import time
+import traceback
+from typing import Callable
+
+from fastapi import Request, Response
+from starlette.middleware.base import BaseHTTPMiddleware
+
+logger = logging.getLogger(__name__)
+
+
+class RequestLoggingMiddleware(BaseHTTPMiddleware):
+    """Log all HTTP requests with timing and status codes."""
+
+    async def dispatch(self, request: Request, call_next: Callable) -> Response:
+        start_time = time.time()
+        client_host = request.client.host if request.client else "unknown"
+
+        # Log the incoming request
+        logger.info(
+            "→ Request: %s %s (client: %s)",
+            request.method,
+            request.url.path,
+            client_host,
+        )
+
+        try:
+            response = await call_next(request)
+            duration = time.time() - start_time
+
+            # Log the response
+            logger.info(
+                "← Response: %s %s → %d (%dms)",
+                request.method,
+                request.url.path,
+                response.status_code,
+                int(duration * 1000),
+            )
+            return response
+
+        except Exception as exc:
+            duration = time.time() - start_time
+            logger.error(
+                "✗ Error: %s %s → %s (%dms)\n%s",
+                request.method,
+                request.url.path,
+                type(exc).__name__,
+                int(duration * 1000),
+                traceback.format_exc(),
+            )
+            raise
+
+
+class ExceptionLoggingMiddleware(BaseHTTPMiddleware):
+    """Catch and log all unhandled exceptions."""
+
+    async def dispatch(self, request: Request, call_next: Callable) -> Response:
+        try:
+            return await call_next(request)
+        except Exception:
+            logger.critical(
+                "Unhandled exception in %s %s:\n%s",
+                request.method,
+                request.url.path,
+                traceback.format_exc(),
+            )
+            raise
+
+
+def configure_logging(level: int = logging.INFO) -> None:
+    """Configure structured logging for the application."""
+    formatter = logging.Formatter(
+        fmt="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S",
+    )
+
+    # Console handler
+    console_handler = logging.StreamHandler(sys.stdout)
+    console_handler.setFormatter(formatter)
+
+    # Configure root logger
+    root_logger = logging.getLogger()
+    root_logger.setLevel(level)
+    root_logger.handlers = [console_handler]
+
+    # Set levels for specific loggers
+    logging.getLogger("uvicorn").setLevel(logging.WARNING)
+    logging.getLogger("uvicorn.access").setLevel(logging.WARNING)
+    logging.getLogger("sqlalchemy.engine").setLevel(logging.WARNING)
+
+    logger.info("Logging configured at level %s", logging.getLevelName(level))
@@ -1,4 +1,5 @@
 import logging
+import os

 from fastapi import FastAPI
 from fastapi.staticfiles import StaticFiles
@@ -12,10 +13,21 @@ from src.api.tool_types import router as tool_types_router
 from src.api.user_config import router as user_config_router
 from src.api.users import router as users_router
 from src.database import SessionLocal, init_database
+from src.logging_config import (
+    ExceptionLoggingMiddleware,
+    RequestLoggingMiddleware,
+    configure_logging,
+)
 from src.models.tool_type import ToolType

+# Configure logging early
+log_level = os.getenv("LOG_LEVEL", "INFO").upper()
+configure_logging(level=getattr(logging, log_level, logging.INFO))
+
 logger = logging.getLogger(__name__)
 app = FastAPI(title="Headquarter API")
+app.add_middleware(RequestLoggingMiddleware)
+app.add_middleware(ExceptionLoggingMiddleware)


 async def _table_exists(session, table_name: str) -> bool: