# app/services/auth_service.py from datetime import datetime, timedelta from jose import jwt from passlib.context import CryptContext from fastapi import HTTPException, UploadFile from bson import ObjectId from app.core.config import SECRET_KEY, ACCESS_TOKEN_EXPIRE_MINUTES, REFRESH_TOKEN_EXPIRE_DAYS from app.core.db import users_collection, fs import logging # Use a module-specific logger so logs are easy to filter logger = logging.getLogger("app.services.auth_service") pwd_context = CryptContext(schemes=["bcrypt"], deprecated="auto") def hash_password(password: str) -> str: """Hash a plaintext password (do NOT log the password).""" logger.debug("hash_password called") hashed = pwd_context.hash(password) logger.debug("Password hashed successfully") return hashed def verify_password(plain_password: str, hashed_password: str) -> bool: """Verify plaintext password against stored hash.""" logger.debug("verify_password called") try: ok = pwd_context.verify(plain_password, hashed_password) logger.debug("Password verification result: %s", ok) return ok except Exception as exc: # Something unexpected happened during verify logger.exception("Error verifying password: %s", exc) return False def create_token(data: dict, expires: timedelta): """Create a JWT token with expiry. `data` should contain 'sub'.""" sub = data.get("sub") logger.debug("create_token called for subject=%s expires=%s", sub, expires) payload = data.copy() payload["exp"] = datetime.utcnow() + expires try: token = jwt.encode(payload, SECRET_KEY, algorithm="HS256") logger.info("JWT created for subject=%s", sub) return token except Exception as exc: logger.exception("Failed to create JWT for subject=%s: %s", sub, exc) raise HTTPException(status_code=500, detail="Token generation failed") from exc def create_access_token(email: str): logger.debug("create_access_token called for email=%s", email) token = create_token({"sub": email}, timedelta(minutes=ACCESS_TOKEN_EXPIRE_MINUTES)) logger.info("Access token generated for %s", email) return token def create_refresh_token(email: str): logger.debug("create_refresh_token called for email=%s", email) token = create_token({"sub": email}, timedelta(days=REFRESH_TOKEN_EXPIRE_DAYS)) logger.info("Refresh token generated for %s", email) return token def _delete_avatar_file_if_exists(file_id: str) -> None: """Delete an avatar file from GridFS if it exists. Non-fatal on failure.""" if not file_id: logger.debug("_delete_avatar_file_if_exists called with empty file_id; skipping") return try: oid = ObjectId(file_id) except Exception: logger.warning("Invalid avatar file_id, skipping delete: %s", file_id) return try: fs.delete(oid) logger.info("Deleted old avatar from GridFS: %s", file_id) except Exception as exc: # Non-fatal: log and continue. Common causes: already deleted or invalid id. logger.warning("Failed to delete avatar %s from GridFS: %s", file_id, exc) def save_avatar(file: UploadFile) -> str: """Save a new avatar to GridFS and return its file id (string).""" logger.debug("save_avatar called filename=%s content_type=%s", getattr(file, "filename", None), getattr(file, "content_type", None)) allowed = ["image/jpeg", "image/png", "image/gif"] if file.content_type not in allowed: logger.warning("Rejected avatar upload due to invalid content type: %s", file.content_type) raise HTTPException(status_code=400, detail="Invalid image type.") # read file content (UploadFile.file is a file-like object) try: contents = file.file.read() except Exception as exc: logger.exception("Failed to read uploaded avatar file: %s", exc) raise HTTPException(status_code=400, detail="Failed to read uploaded file") from exc try: file_id = fs.put(contents, filename=file.filename, contentType=file.content_type) logger.info("Saved avatar to GridFS with id: %s (size=%d bytes)", file_id, len(contents)) return str(file_id) except Exception as exc: logger.exception("Failed to save avatar to GridFS: %s", exc) raise HTTPException(status_code=500, detail="Failed to store avatar") from exc def fetch_user(email: str): """Return the raw user document (or None) by email.""" logger.debug("fetch_user called for email=%s", email) if not email: logger.debug("fetch_user called with empty email") return None try: user = users_collection.find_one({"email": email}) logger.debug("fetch_user found: %s", bool(user)) return user except Exception as exc: logger.exception("Error fetching user %s: %s", email, exc) raise HTTPException(status_code=500, detail="Failed to fetch user") from exc def authenticate(email: str, password: str): """Authenticate user by email and password. Returns user dict or None.""" logger.debug("authenticate called for email=%s", email) user = fetch_user(email) if not user: logger.warning("Authenticate failed: user not found for email=%s", email) return None if not verify_password(password, user.get("hashed_password", "")): logger.warning("Authenticate failed: invalid credentials for email=%s", email) return None logger.info("User authenticated successfully: %s", email) return user def update_user_profile(current_email: str, name: str | None = None, new_email: str | None = None, password: str | None = None, avatar: UploadFile | None = None): """ Update profile fields for the user identified by current_email. If avatar is provided, the old avatar (if any) will be deleted from GridFS. Returns the updated user document (with hashed_password removed). """ logger.info("update_user_profile called for current_email=%s", current_email) if not current_email: logger.error("update_user_profile missing current_email") raise HTTPException(status_code=400, detail="Missing current user email") # Fetch current user to get current avatar id (if any) current_user = fetch_user(current_email) if not current_user: logger.warning("update_user_profile user not found: %s", current_email) raise HTTPException(status_code=404, detail="User not found") update_data = {} if name: update_data["name"] = name logger.debug("Will update name for %s", current_email) if new_email: update_data["email"] = new_email logger.debug("Will update email for %s -> %s", current_email, new_email) if password: update_data["hashed_password"] = hash_password(password) logger.debug("Password updated for %s (hashed, not logged)", current_email) if avatar: logger.debug("Avatar upload detected for %s; processing replacement", current_email) # Delete the old avatar first (if exists) old_avatar_id = current_user.get("avatar") if old_avatar_id: logger.debug("Deleting old avatar id=%s for user=%s", old_avatar_id, current_email) _delete_avatar_file_if_exists(old_avatar_id) # Save the new avatar and set the new id new_file_id = save_avatar(avatar) update_data["avatar"] = new_file_id logger.debug("New avatar saved with id=%s for user=%s", new_file_id, current_email) if not update_data: logger.info("No update parameters provided for %s", current_email) raise HTTPException(status_code=400, detail="No update parameters provided") try: result = users_collection.update_one({"email": current_email}, {"$set": update_data}) except Exception as exc: logger.exception("Failed to update user in DB for %s: %s", current_email, exc) raise HTTPException(status_code=500, detail="Failed to update user") from exc if result.matched_count == 0: logger.warning("Update attempted but user not found during DB update for %s", current_email) raise HTTPException(status_code=404, detail="User not found") # fetch and return the updated document (prefer the new email if changed) lookup_email = new_email if new_email else current_email try: updated_user = users_collection.find_one({"email": lookup_email}) except Exception as exc: logger.exception("Failed to fetch updated user %s: %s", lookup_email, exc) raise HTTPException(status_code=500, detail="Failed to fetch updated user") from exc if not updated_user: logger.error("Updated user document not found after update for %s", lookup_email) raise HTTPException(status_code=500, detail="Updated user not found") # Remove hashed_password before returning user object to any caller if "hashed_password" in updated_user: updated_user.pop("hashed_password", None) logger.debug("Removed hashed_password from returned user object for %s", lookup_email) logger.info("User profile updated successfully for %s", lookup_email) return updated_user