Add MSAL debug logging to frontend and backend
- Frontend: Set MSAL log level to Info, add [MSAL] prefix - Frontend: Add [MSAL Auth] logs for token acquisition - Frontend: Add [MSAL Login] logs for login popup flow - Backend: Add [MSAL Backend] logs for token verification - Backend: Add [MSAL Backend] logs for auth dependency 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
This commit is contained in:
michael
parent
dc17cd087c
commit
04527d65db
5 changed files with 65 additions and 19 deletions
|
|
@ -3,12 +3,15 @@ FastAPI authentication dependencies.
|
|||
|
||||
Provides dependency functions for securing REST endpoints with Azure AD token verification.
|
||||
"""
|
||||
import logging
|
||||
from typing import Optional
|
||||
from fastapi import Header, HTTPException, status
|
||||
|
||||
from app.config import settings
|
||||
from app.services.auth_service import verify_access_token
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
async def get_current_user(authorization: Optional[str] = Header(None)) -> dict:
|
||||
"""
|
||||
|
|
@ -28,20 +31,27 @@ 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")
|
||||
|
||||
# If auth is disabled, return mock user immediately
|
||||
if settings.DISABLE_AUTH:
|
||||
logger.info("[MSAL Backend] Auth disabled - returning mock user")
|
||||
return {"sub": "dev-user", "name": "Development User", "preferred_username": "dev@localhost"}
|
||||
|
||||
if not authorization:
|
||||
logger.warning("[MSAL Backend] Missing authorization header")
|
||||
raise HTTPException(
|
||||
status_code=status.HTTP_401_UNAUTHORIZED,
|
||||
detail="Missing authorization header",
|
||||
headers={"WWW-Authenticate": "Bearer"},
|
||||
)
|
||||
|
||||
logger.info(f"[MSAL Backend] Authorization header present, length: {len(authorization)}")
|
||||
|
||||
# Extract token from "Bearer <token>" format
|
||||
parts = authorization.split()
|
||||
if len(parts) != 2 or parts[0].lower() != "bearer":
|
||||
logger.warning(f"[MSAL Backend] Invalid auth header format: {parts[0] if parts else 'empty'}")
|
||||
raise HTTPException(
|
||||
status_code=status.HTTP_401_UNAUTHORIZED,
|
||||
detail="Invalid authorization header format. Expected: Bearer <token>",
|
||||
|
|
@ -49,13 +59,16 @@ 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...")
|
||||
claims = await verify_access_token(token)
|
||||
|
||||
if not claims:
|
||||
logger.warning("[MSAL Backend] Token verification failed - returning 401")
|
||||
raise HTTPException(
|
||||
status_code=status.HTTP_401_UNAUTHORIZED,
|
||||
detail="Invalid or expired token",
|
||||
headers={"WWW-Authenticate": "Bearer"},
|
||||
)
|
||||
|
||||
logger.info(f"[MSAL Backend] Authentication successful for: {claims.get('name', 'unknown')}")
|
||||
return claims
|
||||
|
|
|
|||
|
|
@ -56,24 +56,34 @@ 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")
|
||||
|
||||
if settings.DISABLE_AUTH:
|
||||
logger.warning("Auth disabled - skipping token verification")
|
||||
logger.warning("[MSAL Backend] Auth disabled - skipping token verification")
|
||||
return {"sub": "dev-user", "name": "Development User", "preferred_username": "dev@localhost"}
|
||||
|
||||
if not token:
|
||||
logger.warning("No token provided")
|
||||
logger.warning("[MSAL Backend] No token provided")
|
||||
return None
|
||||
|
||||
# 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}")
|
||||
|
||||
try:
|
||||
# Get Azure AD public keys
|
||||
logger.info("[MSAL Backend] Fetching Azure AD JWKS...")
|
||||
jwks = await get_azure_jwks()
|
||||
logger.info(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}")
|
||||
|
||||
if not kid:
|
||||
logger.warning("No key ID in token header")
|
||||
logger.warning("[MSAL Backend] No key ID in token header")
|
||||
return None
|
||||
|
||||
# Find the matching key
|
||||
|
|
@ -84,7 +94,7 @@ async def verify_access_token(token: str) -> Optional[dict]:
|
|||
break
|
||||
|
||||
if not rsa_key:
|
||||
logger.warning(f"Key ID {kid} not found in JWKS, refreshing cache")
|
||||
logger.warning(f"[MSAL Backend] Key ID {kid} not found in JWKS, refreshing cache")
|
||||
# Try refreshing JWKS in case keys rotated
|
||||
global _jwks_cache_expiry
|
||||
_jwks_cache_expiry = datetime.min
|
||||
|
|
@ -95,26 +105,34 @@ async def verify_access_token(token: str) -> Optional[dict]:
|
|||
break
|
||||
|
||||
if not rsa_key:
|
||||
logger.error("Could not find matching key after refresh")
|
||||
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}")
|
||||
|
||||
# Verify and decode the token
|
||||
# For ID tokens with OpenID scopes, audience is the client ID
|
||||
# and issuer uses the v2.0 endpoint
|
||||
expected_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] Verifying with issuer: {expected_issuer}")
|
||||
|
||||
claims = jwt.decode(
|
||||
token,
|
||||
rsa_key,
|
||||
algorithms=["RS256"],
|
||||
audience=settings.AZURE_CLIENT_ID,
|
||||
issuer=f"https://login.microsoftonline.com/{settings.AZURE_TENANT_ID}/v2.0",
|
||||
issuer=expected_issuer,
|
||||
)
|
||||
|
||||
logger.info(f"Token verified for user: {claims.get('name', 'unknown')}")
|
||||
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')}")
|
||||
return claims
|
||||
|
||||
except JWTError as e:
|
||||
logger.warning(f"JWT verification failed: {e}")
|
||||
logger.warning(f"[MSAL Backend] JWT verification failed: {e}")
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.error(f"Token verification error: {e}")
|
||||
logger.error(f"[MSAL Backend] Token verification error: {e}")
|
||||
return None
|
||||
|
|
|
|||
|
|
@ -83,19 +83,27 @@ export const Login: React.FC = () => {
|
|||
};
|
||||
|
||||
const handleMicrosoftLogin = async () => {
|
||||
console.log('[MSAL Login] Starting Microsoft login popup...');
|
||||
console.log('[MSAL Login] Login request scopes:', loginRequest.scopes);
|
||||
setIsLoggingIn(true);
|
||||
setLoginError(null);
|
||||
|
||||
try {
|
||||
await instance.loginPopup(loginRequest);
|
||||
const response = await instance.loginPopup(loginRequest);
|
||||
// Success - MSAL Provider will detect the login and re-render App
|
||||
console.log('[MSAL Login] Login successful!');
|
||||
console.log('[MSAL Login] Account:', response.account?.username);
|
||||
console.log('[MSAL Login] Token type:', response.tokenType);
|
||||
console.log('[MSAL Login] Expires on:', response.expiresOn);
|
||||
} catch (error: unknown) {
|
||||
console.error('Login failed:', error);
|
||||
console.error('[MSAL Login] Login failed:', error);
|
||||
if (error instanceof Error) {
|
||||
// Handle user cancellation differently from errors
|
||||
if (error.message.includes('user_cancelled')) {
|
||||
console.log('[MSAL Login] User cancelled login');
|
||||
setLoginError(null); // Don't show error for cancellation
|
||||
} else {
|
||||
console.error('[MSAL Login] Error details:', error.message);
|
||||
setLoginError('Login failed. Please try again or contact support.');
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -20,22 +20,23 @@ export const msalConfig: Configuration = {
|
|||
loggerOptions: {
|
||||
loggerCallback: (level, message, containsPii) => {
|
||||
if (containsPii) return;
|
||||
const prefix = '[MSAL]';
|
||||
switch (level) {
|
||||
case LogLevel.Error:
|
||||
console.error(message);
|
||||
console.error(prefix, message);
|
||||
break;
|
||||
case LogLevel.Warning:
|
||||
console.warn(message);
|
||||
console.warn(prefix, message);
|
||||
break;
|
||||
case LogLevel.Info:
|
||||
console.info(message);
|
||||
console.info(prefix, message);
|
||||
break;
|
||||
case LogLevel.Verbose:
|
||||
console.debug(message);
|
||||
console.debug(prefix, message);
|
||||
break;
|
||||
}
|
||||
},
|
||||
logLevel: LogLevel.Warning,
|
||||
logLevel: LogLevel.Info, // Set to Info for debugging MSAL activity
|
||||
},
|
||||
},
|
||||
};
|
||||
|
|
|
|||
|
|
@ -9,31 +9,37 @@ import { apiTokenRequest } from './authConfig';
|
|||
* Use this before making authenticated API calls.
|
||||
*/
|
||||
export const getAccessToken = async (msalInstance: IPublicClientApplication): Promise<string | null> => {
|
||||
console.log('[MSAL Auth] getAccessToken called');
|
||||
const account = msalInstance.getActiveAccount();
|
||||
if (!account) {
|
||||
console.error('No active account found');
|
||||
console.error('[MSAL Auth] No active account found');
|
||||
return null;
|
||||
}
|
||||
console.log('[MSAL Auth] Active account:', account.username);
|
||||
|
||||
try {
|
||||
// Try silent token acquisition first
|
||||
console.log('[MSAL Auth] Attempting silent token acquisition...');
|
||||
const response = await msalInstance.acquireTokenSilent({
|
||||
...apiTokenRequest,
|
||||
account,
|
||||
});
|
||||
console.log('[MSAL Auth] Silent token acquisition successful, expires:', response.expiresOn);
|
||||
return response.accessToken;
|
||||
} catch (error) {
|
||||
if (error instanceof InteractionRequiredAuthError) {
|
||||
// Fallback to popup if silent fails (e.g., token expired, new consent required)
|
||||
console.log('[MSAL Auth] Silent acquisition failed, trying popup...');
|
||||
try {
|
||||
const response = await msalInstance.acquireTokenPopup(apiTokenRequest);
|
||||
console.log('[MSAL Auth] Popup token acquisition successful');
|
||||
return response.accessToken;
|
||||
} catch (popupError) {
|
||||
console.error('Failed to acquire token via popup:', popupError);
|
||||
console.error('[MSAL Auth] Failed to acquire token via popup:', popupError);
|
||||
return null;
|
||||
}
|
||||
}
|
||||
console.error('Failed to acquire token:', error);
|
||||
console.error('[MSAL Auth] Failed to acquire token:', error);
|
||||
return null;
|
||||
}
|
||||
};
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue