refactor(logging): switch to parameterized logging for improved performance and clarity
- Replaced f-strings with parameterized logging calls across routes, services, and repositories to optimize log message evaluation. - Improved exception handling by using `logger.exception` where appropriate for automatic traceback logging.
This commit is contained in:
@@ -85,7 +85,7 @@ class AuthService:
|
||||
# Delegate creation (hashing + commit) to the repository
|
||||
user = await user_repo.create(db, obj_in=user_data)
|
||||
|
||||
logger.info(f"User created successfully: {user.email}")
|
||||
logger.info("User created successfully: %s", user.email)
|
||||
return user
|
||||
|
||||
except (AuthenticationError, DuplicateError):
|
||||
@@ -94,7 +94,7 @@ class AuthService:
|
||||
except DuplicateEntryError as e:
|
||||
raise DuplicateError(str(e))
|
||||
except Exception as e:
|
||||
logger.error(f"Error creating user: {e!s}", exc_info=True)
|
||||
logger.exception("Error creating user: %s", e)
|
||||
raise AuthenticationError(f"Failed to create user: {e!s}")
|
||||
|
||||
@staticmethod
|
||||
@@ -166,7 +166,7 @@ class AuthService:
|
||||
return AuthService.create_tokens(user)
|
||||
|
||||
except (TokenExpiredError, TokenInvalidError) as e:
|
||||
logger.warning(f"Token refresh failed: {e!s}")
|
||||
logger.warning("Token refresh failed: %s", e)
|
||||
raise
|
||||
|
||||
@staticmethod
|
||||
@@ -201,7 +201,7 @@ class AuthService:
|
||||
new_hash = await get_password_hash_async(new_password)
|
||||
await user_repo.update_password(db, user=user, password_hash=new_hash)
|
||||
|
||||
logger.info(f"Password changed successfully for user {user_id}")
|
||||
logger.info("Password changed successfully for user %s", user_id)
|
||||
return True
|
||||
|
||||
except AuthenticationError:
|
||||
@@ -210,9 +210,7 @@ class AuthService:
|
||||
except Exception as e:
|
||||
# Rollback on any database errors
|
||||
await db.rollback()
|
||||
logger.error(
|
||||
f"Error changing password for user {user_id}: {e!s}", exc_info=True
|
||||
)
|
||||
logger.exception("Error changing password for user %s: %s", user_id, e)
|
||||
raise AuthenticationError(f"Failed to change password: {e!s}")
|
||||
|
||||
@staticmethod
|
||||
@@ -241,5 +239,5 @@ class AuthService:
|
||||
|
||||
new_hash = await get_password_hash_async(new_password)
|
||||
user = await user_repo.update_password(db, user=user, password_hash=new_hash)
|
||||
logger.info(f"Password reset successfully for {email}")
|
||||
logger.info("Password reset successfully for %s", email)
|
||||
return user
|
||||
|
||||
@@ -58,8 +58,8 @@ class ConsoleEmailBackend(EmailBackend):
|
||||
logger.info("=" * 80)
|
||||
logger.info("EMAIL SENT (Console Backend)")
|
||||
logger.info("=" * 80)
|
||||
logger.info(f"To: {', '.join(to)}")
|
||||
logger.info(f"Subject: {subject}")
|
||||
logger.info("To: %s", ", ".join(to))
|
||||
logger.info("Subject: %s", subject)
|
||||
logger.info("-" * 80)
|
||||
if text_content:
|
||||
logger.info("Plain Text Content:")
|
||||
@@ -199,7 +199,7 @@ The {settings.PROJECT_NAME} Team
|
||||
text_content=text_content,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to send password reset email to {to_email}: {e!s}")
|
||||
logger.error("Failed to send password reset email to %s: %s", to_email, e)
|
||||
return False
|
||||
|
||||
async def send_email_verification(
|
||||
@@ -287,7 +287,7 @@ The {settings.PROJECT_NAME} Team
|
||||
text_content=text_content,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to send verification email to {to_email}: {e!s}")
|
||||
logger.error("Failed to send verification email to %s: %s", to_email, e)
|
||||
return False
|
||||
|
||||
|
||||
|
||||
@@ -139,7 +139,7 @@ def verify_pkce(code_verifier: str, code_challenge: str, method: str) -> bool:
|
||||
if method != "S256":
|
||||
# SECURITY: Reject any method other than S256
|
||||
# 'plain' method provides no security against code interception attacks
|
||||
logger.warning(f"PKCE verification rejected for unsupported method: {method}")
|
||||
logger.warning("PKCE verification rejected for unsupported method: %s", method)
|
||||
return False
|
||||
|
||||
# SHA-256 hash, then base64url encode (RFC 7636 Section 4.2)
|
||||
@@ -257,7 +257,9 @@ def validate_scopes(client: OAuthClient, requested_scopes: list[str]) -> list[st
|
||||
# Warn if some scopes were filtered out
|
||||
invalid = requested - allowed
|
||||
if invalid:
|
||||
logger.warning(f"Client {client.client_id} requested invalid scopes: {invalid}")
|
||||
logger.warning(
|
||||
"Client %s requested invalid scopes: %s", client.client_id, invalid
|
||||
)
|
||||
|
||||
return list(valid)
|
||||
|
||||
@@ -320,7 +322,9 @@ async def create_authorization_code(
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Created authorization code for user {user.id} and client {client.client_id}"
|
||||
"Created authorization code for user %s and client %s",
|
||||
user.id,
|
||||
client.client_id,
|
||||
)
|
||||
return code
|
||||
|
||||
@@ -369,7 +373,8 @@ async def exchange_authorization_code(
|
||||
if existing_code and existing_code.used:
|
||||
# Code reuse is a security incident - revoke all tokens for this grant
|
||||
logger.warning(
|
||||
f"Authorization code reuse detected for client {existing_code.client_id}"
|
||||
"Authorization code reuse detected for client %s",
|
||||
existing_code.client_id,
|
||||
)
|
||||
await revoke_tokens_for_user_client(
|
||||
db, UUID(str(existing_code.user_id)), str(existing_code.client_id)
|
||||
@@ -527,7 +532,7 @@ async def create_tokens(
|
||||
ip_address=ip_address,
|
||||
)
|
||||
|
||||
logger.info(f"Issued tokens for user {user.id} to client {client.client_id}")
|
||||
logger.info("Issued tokens for user %s to client %s", user.id, client.client_id)
|
||||
|
||||
return {
|
||||
"access_token": access_token,
|
||||
@@ -580,7 +585,7 @@ async def refresh_tokens(
|
||||
if token_record.revoked:
|
||||
# Token reuse after revocation - security incident
|
||||
logger.warning(
|
||||
f"Revoked refresh token reuse detected for client {token_record.client_id}"
|
||||
"Revoked refresh token reuse detected for client %s", token_record.client_id
|
||||
)
|
||||
raise InvalidGrantError("Refresh token has been revoked")
|
||||
|
||||
@@ -672,7 +677,7 @@ async def revoke_token(
|
||||
raise InvalidClientError("Token was not issued to this client")
|
||||
|
||||
await oauth_provider_token_repo.revoke(db, token=refresh_record)
|
||||
logger.info(f"Revoked refresh token {refresh_record.jti[:8]}...")
|
||||
logger.info("Revoked refresh token %s...", refresh_record.jti[:8])
|
||||
return True
|
||||
|
||||
# Try as access token (JWT)
|
||||
@@ -696,7 +701,7 @@ async def revoke_token(
|
||||
raise InvalidClientError("Token was not issued to this client")
|
||||
await oauth_provider_token_repo.revoke(db, token=refresh_record)
|
||||
logger.info(
|
||||
f"Revoked refresh token via access token JTI {jti[:8]}..."
|
||||
"Revoked refresh token via access token JTI %s...", jti[:8]
|
||||
)
|
||||
return True
|
||||
except JWTError:
|
||||
@@ -731,7 +736,7 @@ async def revoke_tokens_for_user_client(
|
||||
|
||||
if count > 0:
|
||||
logger.warning(
|
||||
f"Revoked {count} tokens for user {user_id} and client {client_id}"
|
||||
"Revoked %s tokens for user %s and client %s", count, user_id, client_id
|
||||
)
|
||||
|
||||
return count
|
||||
@@ -753,7 +758,7 @@ async def revoke_all_user_tokens(db: AsyncSession, user_id: UUID) -> int:
|
||||
count = await oauth_provider_token_repo.revoke_all_for_user(db, user_id=user_id)
|
||||
|
||||
if count > 0:
|
||||
logger.info(f"Revoked {count} OAuth provider tokens for user {user_id}")
|
||||
logger.info("Revoked %s OAuth provider tokens for user %s", count, user_id)
|
||||
|
||||
return count
|
||||
|
||||
|
||||
@@ -219,7 +219,7 @@ class OAuthService:
|
||||
**auth_params,
|
||||
)
|
||||
|
||||
logger.info(f"OAuth authorization URL created for {provider}")
|
||||
logger.info("OAuth authorization URL created for %s", provider)
|
||||
return url, state
|
||||
|
||||
@staticmethod
|
||||
@@ -254,8 +254,9 @@ class OAuthService:
|
||||
# This prevents authorization code injection attacks (RFC 6749 Section 10.6)
|
||||
if state_record.redirect_uri != redirect_uri:
|
||||
logger.warning(
|
||||
f"OAuth redirect_uri mismatch: expected {state_record.redirect_uri}, "
|
||||
f"got {redirect_uri}"
|
||||
"OAuth redirect_uri mismatch: expected %s, got %s",
|
||||
state_record.redirect_uri,
|
||||
redirect_uri,
|
||||
)
|
||||
raise AuthenticationError("Redirect URI mismatch")
|
||||
|
||||
@@ -299,7 +300,7 @@ class OAuthService:
|
||||
except AuthenticationError:
|
||||
raise
|
||||
except Exception as e:
|
||||
logger.error(f"OAuth token exchange failed: {e!s}")
|
||||
logger.error("OAuth token exchange failed: %s", e)
|
||||
raise AuthenticationError("Failed to exchange authorization code")
|
||||
|
||||
# Get user info from provider
|
||||
@@ -312,7 +313,7 @@ class OAuthService:
|
||||
client, provider, config, access_token
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to get user info: {e!s}")
|
||||
logger.error("Failed to get user info: %s", e)
|
||||
raise AuthenticationError(
|
||||
"Failed to get user information from provider"
|
||||
)
|
||||
@@ -353,7 +354,7 @@ class OAuthService:
|
||||
+ timedelta(seconds=token.get("expires_in", 3600)),
|
||||
)
|
||||
|
||||
logger.info(f"OAuth login successful for {user.email} via {provider}")
|
||||
logger.info("OAuth login successful for %s via %s", user.email, provider)
|
||||
|
||||
elif state_record.user_id:
|
||||
# Account linking flow (user is already logged in)
|
||||
@@ -387,7 +388,7 @@ class OAuthService:
|
||||
)
|
||||
await oauth_account.create_account(db, obj_in=oauth_create)
|
||||
|
||||
logger.info(f"OAuth account linked: {provider} -> {user.email}")
|
||||
logger.info("OAuth account linked: %s -> %s", provider, user.email)
|
||||
|
||||
else:
|
||||
# New OAuth login - check for existing user by email
|
||||
@@ -409,7 +410,9 @@ class OAuthService:
|
||||
if existing_provider:
|
||||
# This shouldn't happen if we got here, but safety check
|
||||
logger.warning(
|
||||
f"OAuth account already linked (race condition?): {provider} -> {user.email}"
|
||||
"OAuth account already linked (race condition?): %s -> %s",
|
||||
provider,
|
||||
user.email,
|
||||
)
|
||||
else:
|
||||
# Create OAuth account link
|
||||
@@ -427,7 +430,9 @@ class OAuthService:
|
||||
)
|
||||
await oauth_account.create_account(db, obj_in=oauth_create)
|
||||
|
||||
logger.info(f"OAuth auto-linked by email: {provider} -> {user.email}")
|
||||
logger.info(
|
||||
"OAuth auto-linked by email: %s -> %s", provider, user.email
|
||||
)
|
||||
|
||||
else:
|
||||
# Create new user
|
||||
@@ -447,7 +452,7 @@ class OAuthService:
|
||||
)
|
||||
is_new_user = True
|
||||
|
||||
logger.info(f"New user created via OAuth: {user.email} ({provider})")
|
||||
logger.info("New user created via OAuth: %s (%s)", user.email, provider)
|
||||
|
||||
# Generate JWT tokens
|
||||
claims = {
|
||||
@@ -583,8 +588,9 @@ class OAuthService:
|
||||
token_nonce = payload.get("nonce")
|
||||
if token_nonce != expected_nonce:
|
||||
logger.warning(
|
||||
f"OAuth ID token nonce mismatch: expected {expected_nonce}, "
|
||||
f"got {token_nonce}"
|
||||
"OAuth ID token nonce mismatch: expected %s, got %s",
|
||||
expected_nonce,
|
||||
token_nonce,
|
||||
)
|
||||
raise AuthenticationError("Invalid ID token nonce")
|
||||
|
||||
@@ -592,14 +598,14 @@ class OAuthService:
|
||||
return payload
|
||||
|
||||
except JWTError as e:
|
||||
logger.warning(f"Google ID token verification failed: {e}")
|
||||
logger.warning("Google ID token verification failed: %s", e)
|
||||
raise AuthenticationError("Invalid ID token signature")
|
||||
except httpx.HTTPError as e:
|
||||
logger.error(f"Failed to fetch Google JWKS: {e}")
|
||||
logger.error("Failed to fetch Google JWKS: %s", e)
|
||||
# If we can't verify the ID token, fail closed for security
|
||||
raise AuthenticationError("Failed to verify ID token")
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error verifying Google ID token: {e}")
|
||||
logger.error("Unexpected error verifying Google ID token: %s", e)
|
||||
raise AuthenticationError("ID token verification error")
|
||||
|
||||
@staticmethod
|
||||
@@ -701,7 +707,7 @@ class OAuthService:
|
||||
if not deleted:
|
||||
raise AuthenticationError(f"No {provider} account found to unlink")
|
||||
|
||||
logger.info(f"OAuth provider unlinked: {provider} from {user.email}")
|
||||
logger.info("OAuth provider unlinked: %s from %s", provider, user.email)
|
||||
return True
|
||||
|
||||
@staticmethod
|
||||
|
||||
@@ -35,12 +35,12 @@ async def cleanup_expired_sessions(keep_days: int = 30) -> int:
|
||||
# Use CRUD method to cleanup
|
||||
count = await session_crud.cleanup_expired(db, keep_days=keep_days)
|
||||
|
||||
logger.info(f"Session cleanup complete: {count} sessions deleted")
|
||||
logger.info("Session cleanup complete: %s sessions deleted", count)
|
||||
|
||||
return count
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error during session cleanup: {e!s}", exc_info=True)
|
||||
logger.exception("Error during session cleanup: %s", e)
|
||||
return 0
|
||||
|
||||
|
||||
@@ -79,10 +79,10 @@ async def get_session_statistics() -> dict:
|
||||
"expired": expired_sessions,
|
||||
}
|
||||
|
||||
logger.info(f"Session statistics: {stats}")
|
||||
logger.info("Session statistics: %s", stats)
|
||||
|
||||
return stats
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error getting session statistics: {e!s}", exc_info=True)
|
||||
logger.exception("Error getting session statistics: %s", e)
|
||||
return {}
|
||||
|
||||
Reference in New Issue
Block a user