feat(logging): add comprehensive logging across application layers

Implement detailed logging in models, services, and routers to improve debugging and monitoring
Configure logging setup in app.py with appropriate log levels and handlers
Add error handling with logging for critical operations in user flows

app/app.py

@@ -3,6 +3,29 @@
 from fastapi import FastAPI
 from fastapi.middleware.cors import CORSMiddleware
 from app.routers import user_router, profile_router
+import logging
+import sys
+
+# Configure logging
+logging.basicConfig(
+    level=logging.DEBUG,
+    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
+    handlers=[
+        logging.StreamHandler(sys.stdout),
+        logging.FileHandler('app.log')
+    ]
+)
+
+# Set specific logger levels
+logging.getLogger("user_router").setLevel(logging.DEBUG)
+logging.getLogger("user_service").setLevel(logging.DEBUG)
+logging.getLogger("otp_model").setLevel(logging.DEBUG)
+logging.getLogger("user_model").setLevel(logging.DEBUG)
+logging.getLogger("profile_service").setLevel(logging.DEBUG)
+
+# Reduce noise from other libraries
+logging.getLogger("uvicorn").setLevel(logging.INFO)
+logging.getLogger("fastapi").setLevel(logging.INFO)
 
 app = FastAPI(title="BookMyService User Management Service")
 

app/models/otp_model.py

@@ -3,6 +3,9 @@ from app.core.cache_client import get_redis
 from app.utils.sms_utils import send_sms_otp
 from app.utils.email_utils import send_email_otp
 from app.utils.common_utils import is_email
+import logging
+
+logger = logging.getLogger("otp_model")
 
 class BookMyServiceOTPModel:
     OTP_TTL = 300  # 5 minutes
@@ -11,18 +14,37 @@ class BookMyServiceOTPModel:
 
     @staticmethod
     async def store_otp(identifier: str, phone: str, otp: str, ttl: int = OTP_TTL):
-        redis = await get_redis()
+        logger.info(f"Storing OTP for identifier: {identifier}")
+        
+        try:
+            redis = await get_redis()
+            logger.debug(f"Redis connection established for OTP storage")
 
-        # Rate limit: max 3 OTPs per 10 minutes
-        rate_key = f"otp_rate_limit:{identifier}"
-        attempts = await redis.incr(rate_key)
-        if attempts == 1:
-            await redis.expire(rate_key, BookMyServiceOTPModel.RATE_LIMIT_WINDOW)
-        elif attempts > BookMyServiceOTPModel.RATE_LIMIT_MAX:
-            raise HTTPException(status_code=429, detail="Too many OTP requests. Try again later.")
+            # Rate limit: max 3 OTPs per 10 minutes
+            rate_key = f"otp_rate_limit:{identifier}"
+            logger.debug(f"Checking rate limit with key: {rate_key}")
+            
+            attempts = await redis.incr(rate_key)
+            logger.debug(f"Current OTP attempts for {identifier}: {attempts}")
+            
+            if attempts == 1:
+                await redis.expire(rate_key, BookMyServiceOTPModel.RATE_LIMIT_WINDOW)
+                logger.debug(f"Set rate limit expiry for {identifier}")
+            elif attempts > BookMyServiceOTPModel.RATE_LIMIT_MAX:
+                logger.warning(f"Rate limit exceeded for {identifier}: {attempts} attempts")
+                raise HTTPException(status_code=429, detail="Too many OTP requests. Try again later.")
 
-        # Store OTP
-        await redis.setex(f"bms_otp:{identifier}", ttl, otp)
+            # Store OTP
+            otp_key = f"bms_otp:{identifier}"
+            await redis.setex(otp_key, ttl, otp)
+            logger.info(f"OTP stored successfully for {identifier} with key: {otp_key}, TTL: {ttl}")
+            
+        except HTTPException as e:
+            logger.error(f"HTTP error storing OTP for {identifier}: {e.status_code} - {e.detail}")
+            raise e
+        except Exception as e:
+            logger.error(f"Unexpected error storing OTP for {identifier}: {str(e)}", exc_info=True)
+            raise HTTPException(status_code=500, detail="Failed to store OTP")
     '''
             # Send OTP via SMS, fallback to Email if identifier is email
             try:
@@ -41,13 +63,36 @@ class BookMyServiceOTPModel:
     '''
     @staticmethod
     async def verify_otp(identifier: str, otp: str):
-        redis = await get_redis()
-        key = f"bms_otp:{identifier}"
-        stored = await redis.get(key)
-        if stored and stored == otp:
-            await redis.delete(key)
-            return True
-        return False
+        logger.info(f"Verifying OTP for identifier: {identifier}")
+        logger.debug(f"Provided OTP: {otp}")
+        
+        try:
+            redis = await get_redis()
+            logger.debug("Redis connection established for OTP verification")
+            
+            key = f"bms_otp:{identifier}"
+            logger.debug(f"Looking up OTP with key: {key}")
+            
+            stored = await redis.get(key)
+            logger.debug(f"Stored OTP value: {stored}")
+            
+            if stored:
+                logger.debug(f"OTP found in Redis. Comparing: provided='{otp}' vs stored='{stored}'")
+                if stored == otp:
+                    logger.info(f"OTP verification successful for {identifier}")
+                    await redis.delete(key)
+                    logger.debug(f"OTP deleted from Redis after successful verification")
+                    return True
+                else:
+                    logger.warning(f"OTP mismatch for {identifier}: provided='{otp}' vs stored='{stored}'")
+                    return False
+            else:
+                logger.warning(f"No OTP found in Redis for identifier: {identifier} with key: {key}")
+                return False
+                
+        except Exception as e:
+            logger.error(f"Error verifying OTP for {identifier}: {str(e)}", exc_info=True)
+            return False
 
     @staticmethod
     async def read_otp(identifier: str):

app/models/user_model.py

@@ -2,28 +2,71 @@ from fastapi import HTTPException
 from app.core.nosql_client import db
 from app.utils.common_utils import is_email  # Assumes utility exists
 from app.schemas.user_schema import UserRegisterRequest
+import logging
+
+logger = logging.getLogger("user_model")
 
 class BookMyServiceUserModel:
     collection = db["customers"]
 
     @staticmethod
     async def find_by_email(email: str):
-        return await BookMyServiceUserModel.collection.find_one({"email": email})
+        logger.debug(f"Searching for user by email: {email}")
+        try:
+            user = await BookMyServiceUserModel.collection.find_one({"email": email})
+            if user:
+                logger.debug(f"User found by email: {email}")
+            else:
+                logger.debug(f"No user found with email: {email}")
+            return user
+        except Exception as e:
+            logger.error(f"Error finding user by email {email}: {str(e)}", exc_info=True)
+            return None
 
     @staticmethod
     async def find_by_mobile(mobile: str):
-        return await BookMyServiceUserModel.collection.find_one({"phone": mobile})
+        logger.debug(f"Searching for user by mobile: {mobile}")
+        try:
+            user = await BookMyServiceUserModel.collection.find_one({"phone": mobile})
+            if user:
+                logger.debug(f"User found by mobile: {mobile}")
+            else:
+                logger.debug(f"No user found with mobile: {mobile}")
+            return user
+        except Exception as e:
+            logger.error(f"Error finding user by mobile {mobile}: {str(e)}", exc_info=True)
+            return None
 
     @staticmethod
     async def find_by_identifier(identifier: str):
-        if is_email(identifier):
-            user = await BookMyServiceUserModel.find_by_email(identifier)
-        else:
-            user = await BookMyServiceUserModel.find_by_mobile(identifier)
-
-        if not user:
-            raise HTTPException(status_code=404, detail="User not found with this email or mobile")
-        return user
+        logger.info(f"Finding user by identifier: {identifier}")
+        
+        try:
+            # Determine if identifier is email or mobile
+            is_email_identifier = is_email(identifier)
+            logger.debug(f"Identifier type - is_email: {is_email_identifier}")
+            
+            if is_email_identifier:
+                logger.debug(f"Searching by email for identifier: {identifier}")
+                user = await BookMyServiceUserModel.find_by_email(identifier)
+            else:
+                logger.debug(f"Searching by mobile for identifier: {identifier}")
+                user = await BookMyServiceUserModel.find_by_mobile(identifier)
+
+            if not user:
+                logger.warning(f"User not found with identifier: {identifier}")
+                raise HTTPException(status_code=404, detail="User not found with this email or mobile")
+            
+            logger.info(f"User found successfully for identifier: {identifier}")
+            logger.debug(f"User data keys: {list(user.keys()) if user else 'None'}")
+            return user
+            
+        except HTTPException as e:
+            logger.error(f"HTTP error finding user by identifier {identifier}: {e.status_code} - {e.detail}")
+            raise e
+        except Exception as e:
+            logger.error(f"Unexpected error finding user by identifier {identifier}: {str(e)}", exc_info=True)
+            raise HTTPException(status_code=500, detail="Failed to find user")
 
     @staticmethod
     async def exists_by_email_or_phone(email: str, phone: str) -> bool:

app/routers/user_router.py

@@ -13,17 +13,25 @@ from app.utils.jwt import create_temp_token, decode_token
 from app.utils.social_utils import verify_google_token, verify_apple_token
 import logging
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger("user_router")
 
 router = APIRouter()
 
 # 🔐 Declare API key header scheme (Swagger shows a single token input box)
-api_key_scheme = APIKeyHeader(name="Authorization", auto_error=True)
+api_key_scheme = APIKeyHeader(name="Authorization", auto_error=False)
 
 # 🔍 Bearer token parser
 # More flexible bearer token parser
 def get_bearer_token(api_key: str = Security(api_key_scheme)) -> str:
     try:
+        # Check if Authorization header is missing
+        if not api_key:
+            logger.warning("Missing Authorization header")
+            raise HTTPException(
+                status_code=status.HTTP_401_UNAUTHORIZED,
+                detail="Missing Authorization header"
+            )
+        
         # If "Bearer " prefix is included, strip it
         logger.debug(f"Received Authorization header: {api_key}")
         if api_key.lower().startswith("bearer "):
@@ -32,28 +40,54 @@ def get_bearer_token(api_key: str = Security(api_key_scheme)) -> str:
         # Else, assume it's already a raw JWT
         return api_key
 
+    except HTTPException:
+        # Re-raise HTTP exceptions
+        raise
     except Exception as e:
+        logger.error(f"Error processing Authorization header: {str(e)}")
         raise HTTPException(
             status_code=status.HTTP_401_UNAUTHORIZED,
-            detail="Invalid or missing Authorization token"
+            detail="Invalid Authorization header format"
         )
     
 
 
 @router.post("/send-otp")
 async def send_otp_handler(payload: OTPRequest):
-    identifier = payload.email or payload.phone
-    if not identifier:
-        raise HTTPException(status_code=400, detail="Email or phone required")
+    logger.info(f"OTP request started - email: {payload.email}, phone: {payload.phone}")
     
-    await UserService.send_otp(identifier, payload.phone or "N/A")
-    
-    temp_token = create_temp_token({
-        "sub": identifier,
-        "type": "otp_verification"
-    }, expires_minutes=10)
-
-    return {"message": "OTP sent", "temp_token": temp_token}
+    try:
+        # Validate input
+        identifier = payload.email or payload.phone
+        if not identifier:
+            logger.warning("OTP request failed - neither email nor phone provided")
+            raise HTTPException(status_code=400, detail="Email or phone required")
+        
+        logger.debug(f"Using identifier: {identifier}")
+        
+        # Send OTP via service
+        logger.debug(f"Calling UserService.send_otp with identifier: {identifier}, phone: {payload.phone or 'N/A'}")
+        await UserService.send_otp(identifier, payload.phone or "N/A")
+        logger.info(f"OTP sent successfully to: {identifier}")
+        
+        # Create temporary token
+        logger.debug("Creating temporary token for OTP verification")
+        temp_token = create_temp_token({
+            "sub": identifier,
+            "type": "otp_verification"
+        }, expires_minutes=10)
+        
+        logger.info(f"Temporary token created for: {identifier}")
+        logger.debug(f"Temp token (first 20 chars): {temp_token[:20]}...")
+        
+        return {"message": "OTP sent", "temp_token": temp_token}
+        
+    except HTTPException as e:
+        logger.error(f"OTP request failed - HTTP {e.status_code}: {e.detail}")
+        raise e
+    except Exception as e:
+        logger.error(f"Unexpected error during OTP request: {str(e)}", exc_info=True)
+        raise HTTPException(status_code=500, detail="Internal server error during OTP request")
 
 # 🔐 OTP Login using temporary token
 @router.post("/otp-login", response_model=TokenResponse)
@@ -61,11 +95,47 @@ async def otp_login_handler(
     payload: OTPVerifyRequest,
     temp_token: str = Depends(get_bearer_token)
 ):
-    decoded = decode_token(temp_token)
-    if not decoded or decoded.get("sub") != payload.login_input or decoded.get("type") != "otp_verification":
-        raise HTTPException(status_code=401, detail="Invalid or expired OTP session token")
+    logger.info(f"OTP login attempt started - login_input: {payload.login_input}")
+    logger.debug(f"Received temp_token: {temp_token[:20]}..." if temp_token else "No temp_token received")
     
-    return await UserService.otp_login_handler(payload.login_input, payload.otp)
+    try:
+        # Decode and validate temporary token
+        logger.debug("Attempting to decode temporary token")
+        decoded = decode_token(temp_token)
+        logger.debug(f"Decoded token payload: {decoded}")
+        
+        if not decoded:
+            logger.warning("Failed to decode temporary token - token is invalid or expired")
+            raise HTTPException(status_code=401, detail="Invalid or expired OTP session token")
+        
+        # Validate token subject matches login input
+        token_sub = decoded.get("sub")
+        token_type = decoded.get("type")
+        logger.debug(f"Token subject: {token_sub}, Token type: {token_type}")
+        
+        if token_sub != payload.login_input:
+            logger.warning(f"Token subject mismatch - token_sub: {token_sub}, login_input: {payload.login_input}")
+            raise HTTPException(status_code=401, detail="Invalid or expired OTP session token")
+        
+        if token_type != "otp_verification":
+            logger.warning(f"Invalid token type - expected: otp_verification, got: {token_type}")
+            raise HTTPException(status_code=401, detail="Invalid or expired OTP session token")
+        
+        logger.info(f"Temporary token validation successful for: {payload.login_input}")
+        
+        # Call user service for OTP verification and login
+        logger.debug(f"Calling UserService.otp_login_handler with identifier: {payload.login_input}, otp: {payload.otp}")
+        result = await UserService.otp_login_handler(payload.login_input, payload.otp)
+        
+        logger.info(f"OTP login successful for: {payload.login_input}")
+        return result
+        
+    except HTTPException as e:
+        logger.error(f"OTP login failed for {payload.login_input} - HTTP {e.status_code}: {e.detail}")
+        raise e
+    except Exception as e:
+        logger.error(f"Unexpected error during OTP login for {payload.login_input}: {str(e)}", exc_info=True)
+        raise HTTPException(status_code=500, detail="Internal server error during OTP login")
 
 # 🌐 OAuth Login for Google / Apple
 @router.post("/oauth-login", response_model=TokenResponse)

app/services/user_service.py

@@ -14,31 +14,70 @@ logger = logging.getLogger("user_service")
 class UserService:
     @staticmethod
     async def send_otp(identifier: str, phone: str):
-        # Using dummy OTP for testing
-        otp = "777777"
-        await BookMyServiceOTPModel.store_otp(identifier, phone, otp)
-        logger.debug(f"OTP sent to {identifier}: {otp}")
+        logger.info(f"UserService.send_otp called - identifier: {identifier}, phone: {phone}")
+        
+        try:
+            # Using dummy OTP for testing
+            otp = "777777"
+            logger.debug(f"Generated OTP: {otp} for identifier: {identifier}")
+            
+            await BookMyServiceOTPModel.store_otp(identifier, phone, otp)
+            logger.info(f"OTP stored successfully for identifier: {identifier}")
+            logger.debug(f"OTP sent to {identifier}: {otp}")
+            
+        except Exception as e:
+            logger.error(f"Error in send_otp for identifier {identifier}: {str(e)}", exc_info=True)
+            raise HTTPException(status_code=500, detail="Failed to send OTP")
 
     @staticmethod
     async def otp_login_handler(identifier: str, otp: str):
-        if not await BookMyServiceOTPModel.verify_otp(identifier, otp):
-            logger.info(f"Invalid or expired OTP for identifier: {identifier}")
-            raise HTTPException(status_code=400, detail="Invalid or expired OTP")
-
-        user = await BookMyServiceUserModel.find_by_identifier(identifier)
-        if not user:
-            logger.info(f"No user found for identifier: {identifier}")
-            raise HTTPException(status_code=404, detail="User not found")
-
-        token_data = {
-            "sub": user.get("user_id"),
-            "user_id": user.get("user_id"),
-            "email": user.get("email"),
-            "role": "user",
-            "exp": datetime.utcnow() + timedelta(hours=8)
-        }
-        access_token = jwt.encode(token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
-        return {"access_token": access_token, "token_type": "bearer", "name": user.get("name")}
+        logger.info(f"UserService.otp_login_handler called - identifier: {identifier}, otp: {otp}")
+        
+        try:
+            # Verify OTP
+            logger.debug(f"Verifying OTP for identifier: {identifier}")
+            otp_valid = await BookMyServiceOTPModel.verify_otp(identifier, otp)
+            logger.debug(f"OTP verification result: {otp_valid}")
+            
+            if not otp_valid:
+                logger.warning(f"Invalid or expired OTP for identifier: {identifier}")
+                raise HTTPException(status_code=400, detail="Invalid or expired OTP")
+            
+            logger.info(f"OTP verification successful for identifier: {identifier}")
+            
+            # Find user by identifier
+            logger.debug(f"Looking up user by identifier: {identifier}")
+            user = await BookMyServiceUserModel.find_by_identifier(identifier)
+            logger.debug(f"User lookup result: {user is not None}")
+            
+            if not user:
+                logger.warning(f"No user found for identifier: {identifier}")
+                raise HTTPException(status_code=404, detail="User not found")
+            
+            logger.info(f"User found for identifier: {identifier}, user_id: {user.get('user_id')}")
+            
+            # Create JWT token
+            logger.debug("Creating JWT token for authenticated user")
+            token_data = {
+                "sub": user.get("user_id"),
+                "user_id": user.get("user_id"),
+                "email": user.get("email"),
+                "role": "user",
+                "exp": datetime.utcnow() + timedelta(hours=8)
+            }
+            logger.debug(f"Token data: {token_data}")
+            
+            access_token = jwt.encode(token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
+            logger.info(f"JWT token created successfully for user: {user.get('user_id')}")
+            
+            return {"access_token": access_token, "token_type": "bearer", "name": user.get("name")}
+            
+        except HTTPException as e:
+            logger.error(f"HTTP error in otp_login_handler for {identifier}: {e.status_code} - {e.detail}")
+            raise e
+        except Exception as e:
+            logger.error(f"Unexpected error in otp_login_handler for {identifier}: {str(e)}", exc_info=True)
+            raise HTTPException(status_code=500, detail="Internal server error during login")
 
     @staticmethod
     async def register(data: UserRegisterRequest, decoded):