diff --git a/backend/app/dependencies/auth.py b/backend/app/dependencies/auth.py index ab6c71b..5f89305 100755 --- a/backend/app/dependencies/auth.py +++ b/backend/app/dependencies/auth.py @@ -31,11 +31,11 @@ async def get_current_user(authorization: Optional[str] = Header(None)) -> dict: Raises: HTTPException: 401 if token is missing or invalid """ - logger.info("[MSAL Backend] get_current_user dependency called") + logger.debug("[MSAL Backend] get_current_user dependency called") # If auth is disabled, return mock user immediately if settings.DISABLE_AUTH: - logger.info("[MSAL Backend] Auth disabled - returning mock user") + logger.debug("[MSAL Backend] Auth disabled - returning mock user") return {"sub": "dev-user", "name": "Development User", "preferred_username": "dev@localhost"} if not authorization: @@ -46,7 +46,7 @@ async def get_current_user(authorization: Optional[str] = Header(None)) -> dict: headers={"WWW-Authenticate": "Bearer"}, ) - logger.info(f"[MSAL Backend] Authorization header present, length: {len(authorization)}") + logger.debug(f"[MSAL Backend] Authorization header present, length: {len(authorization)}") # Extract token from "Bearer " format parts = authorization.split() @@ -59,7 +59,7 @@ async def get_current_user(authorization: Optional[str] = Header(None)) -> dict: ) token = parts[1] - logger.info("[MSAL Backend] Extracted Bearer token, calling verify_access_token...") + logger.debug("[MSAL Backend] Extracted Bearer token, calling verify_access_token...") claims = await verify_access_token(token) if not claims: @@ -70,5 +70,5 @@ async def get_current_user(authorization: Optional[str] = Header(None)) -> dict: headers={"WWW-Authenticate": "Bearer"}, ) - logger.info(f"[MSAL Backend] Authentication successful for: {claims.get('name', 'unknown')}") + logger.debug(f"[MSAL Backend] Authentication successful for: {claims.get('name', 'unknown')}") return claims diff --git a/backend/app/services/auth_service.py b/backend/app/services/auth_service.py index 4b4b126..a7d95ae 100755 --- a/backend/app/services/auth_service.py +++ b/backend/app/services/auth_service.py @@ -37,7 +37,7 @@ async def get_azure_jwks() -> dict: response.raise_for_status() _jwks_cache = response.json() _jwks_cache_expiry = datetime.utcnow() + timedelta(hours=24) - logger.info("Successfully fetched Azure AD JWKS") + logger.debug("Successfully fetched Azure AD JWKS") return _jwks_cache except Exception as e: logger.error(f"Failed to fetch JWKS: {e}") @@ -56,7 +56,7 @@ async def verify_access_token(token: str) -> Optional[dict]: Returns: The token claims dict if valid, None if invalid """ - logger.info("[MSAL Backend] verify_access_token called") + logger.debug("[MSAL Backend] verify_access_token called") if settings.DISABLE_AUTH: logger.warning("[MSAL Backend] Auth disabled - skipping token verification") @@ -68,26 +68,26 @@ async def verify_access_token(token: str) -> Optional[dict]: # Log token preview (first/last chars only for security) token_preview = f"{token[:20]}...{token[-10:]}" if len(token) > 30 else "[short token]" - logger.info(f"[MSAL Backend] Verifying token: {token_preview}") + logger.debug(f"[MSAL Backend] Verifying token: {token_preview}") try: # Get Azure AD public keys - logger.info("[MSAL Backend] Fetching Azure AD JWKS...") + logger.debug("[MSAL Backend] Fetching Azure AD JWKS...") jwks = await get_azure_jwks() - logger.info(f"[MSAL Backend] JWKS contains {len(jwks.get('keys', []))} keys") + logger.debug(f"[MSAL Backend] JWKS contains {len(jwks.get('keys', []))} keys") # Decode without verification first to get the key ID unverified_header = jwt.get_unverified_header(token) kid = unverified_header.get("kid") alg = unverified_header.get("alg") - logger.info(f"[MSAL Backend] Token header - kid: {kid}, alg: {alg}") + logger.debug(f"[MSAL Backend] Token header - kid: {kid}, alg: {alg}") # Log unverified claims to see what we're receiving try: unverified_claims = jwt.get_unverified_claims(token) - logger.info(f"[MSAL Backend] Token aud (unverified): {unverified_claims.get('aud')}") - logger.info(f"[MSAL Backend] Token iss (unverified): {unverified_claims.get('iss')}") - logger.info(f"[MSAL Backend] Token azp (unverified): {unverified_claims.get('azp')}") + logger.debug(f"[MSAL Backend] Token aud (unverified): {unverified_claims.get('aud')}") + logger.debug(f"[MSAL Backend] Token iss (unverified): {unverified_claims.get('iss')}") + logger.debug(f"[MSAL Backend] Token azp (unverified): {unverified_claims.get('azp')}") except Exception as e: logger.warning(f"[MSAL Backend] Could not decode unverified claims: {e}") @@ -117,7 +117,7 @@ async def verify_access_token(token: str) -> Optional[dict]: logger.error("[MSAL Backend] Could not find matching key after refresh") return None - logger.info(f"[MSAL Backend] Found matching RSA key for kid: {kid}") + logger.debug(f"[MSAL Backend] Found matching RSA key for kid: {kid}") # Verify and decode the token # Azure AD can issue tokens with either v1.0 or v2.0 issuer format @@ -125,8 +125,8 @@ async def verify_access_token(token: str) -> Optional[dict]: v1_issuer = f"https://sts.windows.net/{settings.AZURE_TENANT_ID}/" v2_issuer = f"https://login.microsoftonline.com/{settings.AZURE_TENANT_ID}/v2.0" - logger.info(f"[MSAL Backend] Verifying with audience: {settings.AZURE_CLIENT_ID}") - logger.info(f"[MSAL Backend] Accepting issuers: {v1_issuer} OR {v2_issuer}") + logger.debug(f"[MSAL Backend] Verifying with audience: {settings.AZURE_CLIENT_ID}") + logger.debug(f"[MSAL Backend] Accepting issuers: {v1_issuer} OR {v2_issuer}") # Try v1 issuer first (most common for /.default scope tokens) claims = None @@ -139,7 +139,7 @@ async def verify_access_token(token: str) -> Optional[dict]: audience=settings.AZURE_CLIENT_ID, issuer=issuer, ) - logger.info(f"[MSAL Backend] Token verified with issuer: {issuer}") + logger.debug(f"[MSAL Backend] Token verified with issuer: {issuer}") break except JWTError as e: if "issuer" in str(e).lower(): @@ -150,9 +150,9 @@ async def verify_access_token(token: str) -> Optional[dict]: logger.warning("[MSAL Backend] Token issuer doesn't match any expected format") return None - logger.info(f"[MSAL Backend] Token verified successfully!") - logger.info(f"[MSAL Backend] User: {claims.get('name', 'unknown')} ({claims.get('preferred_username', 'unknown')})") - logger.info(f"[MSAL Backend] Token exp: {claims.get('exp')}, iat: {claims.get('iat')}") + logger.debug(f"[MSAL Backend] Token verified successfully!") + logger.debug(f"[MSAL Backend] User: {claims.get('name', 'unknown')} ({claims.get('preferred_username', 'unknown')})") + logger.debug(f"[MSAL Backend] Token exp: {claims.get('exp')}, iat: {claims.get('iat')}") return claims except JWTError as e: