Oliver/modcomms
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Reduce auth logging verbosity: INFO → DEBUG

Browse source 
All routine MSAL token verification logs now use DEBUG level so they
don't flood the console on every polling request.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
michael 2026-02-12 16:13:25 -06:00
parent 7835f557aa
commit ba9c0ebde3
2 changed files with 21 additions and 21 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

10
backend/app/dependencies/auth.py
View file

@ -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 <token>" 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

32
backend/app/services/auth_service.py
View file

@ -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: