diff --git a/apps/api/src/api/auth.py b/apps/api/src/api/auth.py index 6347484..73a3549 100644 --- a/apps/api/src/api/auth.py +++ b/apps/api/src/api/auth.py @@ -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} diff --git a/apps/api/src/logging_config.py b/apps/api/src/logging_config.py new file mode 100644 index 0000000..df3a3f7 --- /dev/null +++ b/apps/api/src/logging_config.py @@ -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)) diff --git a/apps/api/src/main.py b/apps/api/src/main.py index 67e9996..043f656 100644 --- a/apps/api/src/main.py +++ b/apps/api/src/main.py @@ -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: