refactor(logging): change debug to info level for operational logs

Standardize logging level to INFO across application components to ensure important operational logs are captured in production. This provides better visibility into system behavior while reducing noise from debug logs.

app/app.py

@@ -8,14 +8,15 @@ from app.middleware.security_middleware import SecurityMiddleware
 import logging
 import sys
 
-# Configure logging
+# Configure logging (force ensures this overrides any prior configs)
 logging.basicConfig(
-    level=logging.DEBUG,
+    level=logging.INFO,
     format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
     handlers=[
         logging.StreamHandler(sys.stdout),
         logging.FileHandler('app.log')
-    ]
+    ],
+    force=True,
 )
 
 # Set specific logger levels

app/middleware/security_middleware.py

@@ -6,8 +6,7 @@ import logging
 from typing import Dict, Any
 from app.core.nosql_client import db
 
-# Configure logging
-logging.basicConfig(level=logging.INFO)
+# Use app-level logging configuration
 logger = logging.getLogger(__name__)
 
 class SecurityMiddleware(BaseHTTPMiddleware):

app/models/favorite_model.py

@@ -165,7 +165,7 @@ class BookMyServiceFavoriteModel:
     @staticmethod
     async def is_favorite(customer_id: str, merchant_id: str) -> bool:
         """Check if a merchant is in user's favorites"""
-        logger.debug(f"Checking if merchant {merchant_id} is favorite for customer {customer_id}")
+        logger.info(f"Checking if merchant {merchant_id} is favorite for customer {customer_id}")
         
         try:
             favorite = await BookMyServiceFavoriteModel.collection.find_one({

app/models/otp_model.py

@@ -23,7 +23,7 @@ class BookMyServiceOTPModel:
         
         try:
             redis = await get_redis()
-            logger.debug(f"Redis connection established for OTP storage")
+            logger.info(f"Redis connection established for OTP storage")
 
             # Check if account is locked
             if await BookMyServiceOTPModel.is_account_locked(identifier):
@@ -32,14 +32,14 @@ class BookMyServiceOTPModel:
 
             # Rate limit: max 3 OTPs per identifier per 10 minutes
             rate_key = f"otp_rate_limit:{identifier}"
-            logger.debug(f"Checking rate limit with key: {rate_key}")
+            logger.info(f"Checking rate limit with key: {rate_key}")
             
             attempts = await redis.incr(rate_key)
-            logger.debug(f"Current OTP attempts for {identifier}: {attempts}")
+            logger.info(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}")
+                logger.info(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.")
@@ -85,11 +85,11 @@ class BookMyServiceOTPModel:
     @staticmethod
     async def verify_otp(identifier: str, otp: str, client_ip: str = None):
         logger.info(f"Verifying OTP for identifier: {identifier}, IP: {client_ip}")
-        logger.debug(f"Provided OTP: {otp}")
+        logger.info(f"Provided OTP: {otp}")
         
         try:
             redis = await get_redis()
-            logger.debug("Redis connection established for OTP verification")
+            logger.info("Redis connection established for OTP verification")
             
             # Check if account is locked
             if await BookMyServiceOTPModel.is_account_locked(identifier):
@@ -97,19 +97,19 @@ class BookMyServiceOTPModel:
                 raise HTTPException(status_code=423, detail="Account temporarily locked due to too many failed attempts")
             
             key = f"bms_otp:{identifier}"
-            logger.debug(f"Looking up OTP with key: {key}")
+            logger.info(f"Looking up OTP with key: {key}")
             
             stored = await redis.get(key)
-            logger.debug(f"Stored OTP value: {stored}")
+            logger.info(f"Stored OTP value: {stored}")
             
             if stored:
-                logger.debug(f"OTP found in Redis. Comparing: provided='{otp}' vs stored='{stored}'")
+                logger.info(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)
                     # Clear failed attempts on successful verification
                     await BookMyServiceOTPModel.clear_failed_attempts(identifier)
-                    logger.debug(f"OTP deleted from Redis after successful verification")
+                    logger.info(f"OTP deleted from Redis after successful verification")
                     return True
                 else:
                     logger.warning(f"OTP mismatch for {identifier}: provided='{otp}' vs stored='{stored}'")
@@ -166,7 +166,7 @@ class BookMyServiceOTPModel:
                 if ip_attempts == 1:
                     await redis.expire(ip_failed_key, BookMyServiceOTPModel.FAILED_ATTEMPTS_WINDOW)
                 
-                logger.debug(f"IP {client_ip} failed attempts: {ip_attempts}")
+                logger.info(f"IP {client_ip} failed attempts: {ip_attempts}")
             
         except Exception as e:
             logger.error(f"Error tracking failed attempt for {identifier}: {str(e)}", exc_info=True)
@@ -178,7 +178,7 @@ class BookMyServiceOTPModel:
             redis = await get_redis()
             failed_key = f"failed_otp:{identifier}"
             await redis.delete(failed_key)
-            logger.debug(f"Cleared failed attempts for {identifier}")
+            logger.info(f"Cleared failed attempts for {identifier}")
         except Exception as e:
             logger.error(f"Error clearing failed attempts for {identifier}: {str(e)}", exc_info=True)
 

app/models/social_security_model.py

@@ -52,7 +52,7 @@ class SocialSecurityModel:
             if count == 1:
                 await redis.expire(rate_key, SocialSecurityModel.OAUTH_RATE_LIMIT_WINDOW)
                 
-            logger.debug(f"OAuth rate limit count for {client_ip}:{provider} = {count}")
+            logger.info(f"OAuth rate limit count for {client_ip}:{provider} = {count}")
             
         except Exception as e:
             logger.error(f"Error incrementing OAuth rate limit: {str(e)}", exc_info=True)
@@ -76,7 +76,7 @@ class SocialSecurityModel:
                 await SocialSecurityModel.lock_oauth_ip(client_ip, provider)
                 logger.warning(f"IP {client_ip} locked for provider {provider} after {attempts} failed attempts")
             
-            logger.debug(f"OAuth failed attempts for {client_ip}:{provider} = {attempts}")
+            logger.info(f"OAuth failed attempts for {client_ip}:{provider} = {attempts}")
             
         except Exception as e:
             logger.error(f"Error tracking OAuth failed attempt: {str(e)}", exc_info=True)
@@ -117,7 +117,7 @@ class SocialSecurityModel:
             redis = await get_redis()
             failed_key = f"oauth_failed:{client_ip}:{provider}"
             await redis.delete(failed_key)
-            logger.debug(f"Cleared OAuth failed attempts for {client_ip}:{provider}")
+            logger.info(f"Cleared OAuth failed attempts for {client_ip}:{provider}")
         except Exception as e:
             logger.error(f"Error clearing OAuth failed attempts: {str(e)}", exc_info=True)
     

app/models/user_model.py

@@ -11,13 +11,13 @@ class BookMyServiceUserModel:
 
     @staticmethod
     async def find_by_email(email: str):
-        logger.debug(f"Searching for user by email: {email}")
+        logger.info(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}")
+                logger.info(f"User found by email: {email}")
             else:
-                logger.debug(f"No user found with email: {email}")
+                logger.info(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)
@@ -25,13 +25,13 @@ class BookMyServiceUserModel:
 
     @staticmethod
     async def find_by_phone(phone: str):
-        logger.debug(f"Searching for user by phone: {phone}")
+        logger.info(f"Searching for user by phone: {phone}")
         try:
             user = await BookMyServiceUserModel.collection.find_one({"phone": phone})
             if user:
-                logger.debug(f"User found by phone: {phone}")
+                logger.info(f"User found by phone: {phone}")
             else:
-                logger.debug(f"No user found with phone: {phone}")
+                logger.info(f"No user found with phone: {phone}")
             return user
         except Exception as e:
             logger.error(f"Error finding user by phone {phone}: {str(e)}", exc_info=True)
@@ -40,7 +40,7 @@ class BookMyServiceUserModel:
     @staticmethod
     async def find_by_mobile(mobile: str):
         """Legacy method for backward compatibility - redirects to find_by_phone"""
-        logger.debug(f"Legacy find_by_mobile called, redirecting to find_by_phone for: {mobile}")
+        logger.info(f"Legacy find_by_mobile called, redirecting to find_by_phone for: {mobile}")
         return await BookMyServiceUserModel.find_by_phone(mobile)
 
     @staticmethod
@@ -50,13 +50,13 @@ class BookMyServiceUserModel:
         try:
             # Validate and determine identifier type
             identifier_type = validate_identifier(identifier)
-            logger.debug(f"Identifier type determined: {identifier_type}")
+            logger.info(f"Identifier type determined: {identifier_type}")
             
             if identifier_type == "email":
-                logger.debug(f"Searching by email for identifier: {identifier}")
+                logger.info(f"Searching by email for identifier: {identifier}")
                 user = await BookMyServiceUserModel.find_by_email(identifier)
             elif identifier_type == "phone":
-                logger.debug(f"Searching by phone for identifier: {identifier}")
+                logger.info(f"Searching by phone for identifier: {identifier}")
                 user = await BookMyServiceUserModel.find_by_phone(identifier)
             else:
                 logger.error(f"Invalid identifier type: {identifier_type}")
@@ -67,7 +67,7 @@ class BookMyServiceUserModel:
                 raise HTTPException(status_code=404, detail="User not found with this email or phone")
             
             logger.info(f"User found successfully for identifier: {identifier}")
-            logger.debug(f"User data keys: {list(user.keys()) if user else 'None'}")
+            logger.info(f"User data keys: {list(user.keys()) if user else 'None'}")
             return user
             
         except ValueError as ve:

app/routers/user_router.py

@@ -40,7 +40,7 @@ def get_bearer_token(api_key: str = Security(api_key_scheme)) -> str:
             )
         
         # If "Bearer " prefix is included, strip it
-        logger.debug(f"Received Authorization header: {api_key}")
+        logger.info(f"Received Authorization header: {api_key}")
         if api_key.lower().startswith("bearer "):
             return api_key[7:]  # Remove "Bearer " prefix
 
@@ -67,7 +67,7 @@ async def send_otp_login_handler(payload: OTPRequestWithLogin):
         # Validate identifier format
         try:
             identifier_type = validate_identifier(payload.login_input)
-            logger.debug(f"Login input type: {identifier_type}")
+            logger.info(f"Login input type: {identifier_type}")
         except ValueError as ve:
             logger.error(f"Invalid login input format: {str(ve)}")
             raise HTTPException(status_code=400, detail=str(ve))
@@ -79,22 +79,22 @@ async def send_otp_login_handler(payload: OTPRequestWithLogin):
         elif identifier_type == "phone":
             user_exists = await BookMyServiceUserModel.exists_by_email_or_phone(phone=payload.login_input)
         
-        logger.debug(f"User existence check result: {user_exists}")
+        logger.info(f"User existence check result: {user_exists}")
         
         # Send OTP via service
-        logger.debug(f"Calling UserService.send_otp with identifier: {payload.login_input}")
+        logger.info(f"Calling UserService.send_otp with identifier: {payload.login_input}")
         await UserService.send_otp(payload.login_input)
         logger.info(f"OTP sent successfully to: {payload.login_input}")
         
         # Create temporary token
-        logger.debug("Creating temporary token for OTP verification")
+        logger.info("Creating temporary token for OTP verification")
         temp_token = create_temp_token({
             "sub": payload.login_input,
             "type": "otp_verification"
         }, expires_minutes=10)
         
         logger.info(f"Temporary token created for: {payload.login_input}")
-        logger.debug(f"Temp token (first 20 chars): {temp_token[:20]}...")
+        logger.info(f"Temp token (first 20 chars): {temp_token[:20]}...")
         
         return {
             "message": "OTP sent", 
@@ -116,13 +116,13 @@ async def otp_login_handler(
     temp_token: str = Depends(get_bearer_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")
+    logger.info(f"Received temp_token: {temp_token[:20]}..." if temp_token else "No temp_token received")
     
     try:
         # Decode and validate temporary token
-        logger.debug("Attempting to decode temporary token")
+        logger.info("Attempting to decode temporary token")
         decoded = decode_token(temp_token)
-        logger.debug(f"Decoded token payload: {decoded}")
+        logger.info(f"Decoded token payload: {decoded}")
         
         if not decoded:
             logger.warning("Failed to decode temporary token - token is invalid or expired")
@@ -131,7 +131,7 @@ async def otp_login_handler(
         # 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}")
+        logger.info(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}")
@@ -144,7 +144,7 @@ async def otp_login_handler(
         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}")
+        logger.info(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}")
@@ -257,7 +257,7 @@ async def oauth_login_handler(payload: OAuthLoginRequest, request: Request):
         }, expires_minutes=10)
 
         # Log temporary OAuth session token (truncated)
-        logger.debug(f"OAuth temp token generated (first 25 chars): {temp_token[:25]}...")
+        logger.info(f"OAuth temp token generated (first 25 chars): {temp_token[:25]}...")
 
         return {"access_token": temp_token, "token_type": "bearer", "user_exists": user_exists}
         
@@ -291,9 +291,9 @@ async def register_user(
         at = result.get("access_token")
         rt = result.get("refresh_token")
         if at:
-            logger.debug(f"Register access token (first 25 chars): {at[:25]}...")
+            logger.info(f"Register access token (first 25 chars): {at[:25]}...")
         if rt:
-            logger.debug(f"Register refresh token (first 25 chars): {rt[:25]}...")
+            logger.info(f"Register refresh token (first 25 chars): {rt[:25]}...")
     return result
 
 # 🔄 Refresh access token using refresh token
@@ -304,7 +304,7 @@ async def refresh_token_handler(refresh_token: str = Depends(get_bearer_token)):
     try:
         # Decode and validate refresh token
         decoded = decode_token(refresh_token)
-        logger.debug(f"Decoded refresh token payload: {decoded}")
+        logger.info(f"Decoded refresh token payload: {decoded}")
         
         if not decoded:
             logger.warning("Failed to decode refresh token - token is invalid or expired")

app/services/user_service.py

@@ -24,7 +24,7 @@ class UserService:
         try:
             # Validate identifier format
             identifier_type = validate_identifier(identifier)
-            logger.debug(f"Identifier type: {identifier_type}")
+            logger.info(f"Identifier type: {identifier_type}")
             
             # Enhanced rate limiting by IP and identifier
             if client_ip:
@@ -46,7 +46,7 @@ class UserService:
                 
             # Generate OTP - hardcoded for testing purposes
             otp = '777777'
-            logger.debug(f"Generated hardcoded OTP for identifier: {identifier}")
+            logger.info(f"Generated hardcoded OTP for identifier: {identifier}")
             
             await BookMyServiceOTPModel.store_otp(identifier, phone_number, otp)
             
@@ -55,7 +55,7 @@ class UserService:
                 await BookMyServiceOTPModel.increment_rate_limit(ip_rate_key, 3600)  # 1 hour window
             
             logger.info(f"OTP stored successfully for identifier: {identifier}")
-            logger.debug(f"OTP sent to {identifier}")
+            logger.info(f"OTP sent to {identifier}")
             
         except ValueError as ve:
             logger.error(f"Validation error for identifier {identifier}: {str(ve)}")
@@ -71,7 +71,7 @@ class UserService:
         try:
             # Validate identifier format
             identifier_type = validate_identifier(identifier)
-            logger.debug(f"Identifier type: {identifier_type}")
+            logger.info(f"Identifier type: {identifier_type}")
             
             # Check if account is locked
             if await BookMyServiceOTPModel.is_account_locked(identifier):
@@ -79,9 +79,9 @@ class UserService:
                 raise HTTPException(status_code=423, detail="Account temporarily locked due to too many failed attempts")
             
             # Verify OTP with client IP tracking
-            logger.debug(f"Verifying OTP for identifier: {identifier}")
+            logger.info(f"Verifying OTP for identifier: {identifier}")
             otp_valid = await BookMyServiceOTPModel.verify_otp(identifier, otp, client_ip)
-            logger.debug(f"OTP verification result: {otp_valid}")
+            logger.info(f"OTP verification result: {otp_valid}")
             
             if not otp_valid:
                 logger.warning(f"Invalid or expired OTP for identifier: {identifier}")
@@ -94,9 +94,9 @@ class UserService:
             logger.info(f"OTP verification successful for identifier: {identifier}")
             
             # Find user by identifier
-            logger.debug(f"Looking up user by identifier: {identifier}")
+            logger.info(f"Looking up user by identifier: {identifier}")
             user = await BookMyServiceUserModel.find_by_identifier(identifier)
-            logger.debug(f"User lookup result: {user is not None}")
+            logger.info(f"User lookup result: {user is not None}")
             
             if not user:
                 logger.warning(f"No user found for identifier: {identifier}")
@@ -105,12 +105,12 @@ class UserService:
             logger.info(f"User found for identifier: {identifier}, customer_id: {user.get('customer_id')}")
             
             # Create JWT token
-            logger.debug("Creating JWT token for authenticated user")
+            logger.info("Creating JWT token for authenticated user")
             token_data = {
                 "sub": user.get("customer_id"),
                 "exp": datetime.utcnow() + timedelta(hours=8)
             }
-            logger.debug(f"Token data: {token_data}")
+            logger.info(f"Token data: {token_data}")
             
             access_token = jwt.encode(token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
             
@@ -122,8 +122,8 @@ class UserService:
             refresh_token = jwt.encode(refresh_token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
             
             # Log generated tokens (truncated for security)
-            logger.debug(f"Access token generated (first 25 chars): {access_token[:25]}...")
-            logger.debug(f"Refresh token generated (first 25 chars): {refresh_token[:25]}...")
+            logger.info(f"Access token generated (first 25 chars): {access_token[:25]}...")
+            logger.info(f"Refresh token generated (first 25 chars): {refresh_token[:25]}...")
             
             logger.info(f"JWT tokens created successfully for user: {user.get('customer_id')}")
             
@@ -174,7 +174,7 @@ class UserService:
                 identifier_type = validate_identifier(identifier)
                 if identifier_type != "phone":
                     raise ValueError("Phone number format is invalid")
-                logger.debug(f"Registration identifier type: {identifier_type}")
+                logger.info(f"Registration identifier type: {identifier_type}")
             except ValueError as ve:
                 logger.error(f"Invalid phone format during registration: {str(ve)}")
                 raise HTTPException(status_code=400, detail=str(ve))
@@ -230,8 +230,8 @@ class UserService:
                     refresh_token = jwt.encode(refresh_token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
                     
                     # Log generated tokens for existing linked user (truncated)
-                    logger.debug(f"Access token for existing user (first 25 chars): {access_token[:25]}...")
-                    logger.debug(f"Refresh token for existing user (first 25 chars): {refresh_token[:25]}...")
+                    logger.info(f"Access token for existing user (first 25 chars): {access_token[:25]}...")
+                    logger.info(f"Refresh token for existing user (first 25 chars): {refresh_token[:25]}...")
                     
                     return {
                         "access_token": access_token,
@@ -297,8 +297,8 @@ class UserService:
         refresh_token = jwt.encode(refresh_token_data, settings.SECRET_KEY, algorithm=settings.ALGORITHM)
         
         # Log generated tokens for new registration (truncated)
-        logger.debug(f"Access token on register (first 25 chars): {access_token[:25]}...")
-        logger.debug(f"Refresh token on register (first 25 chars): {refresh_token[:25]}...")
+        logger.info(f"Access token on register (first 25 chars): {access_token[:25]}...")
+        logger.info(f"Refresh token on register (first 25 chars): {refresh_token[:25]}...")
         
         return {
             "access_token": access_token,