MukeshKapoor25's picture
refactor(logging): change debug to info level for operational logs
df8187a
from fastapi import HTTPException
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
RATE_LIMIT_MAX = 3
RATE_LIMIT_WINDOW = 600 # 10 minutes
IP_RATE_LIMIT_MAX = 10 # Max 10 OTPs per IP per hour
IP_RATE_LIMIT_WINDOW = 3600 # 1 hour
FAILED_ATTEMPTS_MAX = 5 # Max 5 failed attempts before lock
FAILED_ATTEMPTS_WINDOW = 3600 # 1 hour
ACCOUNT_LOCK_DURATION = 1800 # 30 minutes
@staticmethod
async def store_otp(identifier: str, phone: str, otp: str, ttl: int = OTP_TTL, client_ip: str = None):
logger.info(f"Storing OTP for identifier: {identifier}, IP: {client_ip}")
try:
redis = await get_redis()
logger.info(f"Redis connection established for OTP storage")
# Check if account is locked
if await BookMyServiceOTPModel.is_account_locked(identifier):
logger.warning(f"Account locked for identifier: {identifier}")
raise HTTPException(status_code=423, detail="Account temporarily locked due to too many failed attempts")
# Rate limit: max 3 OTPs per identifier per 10 minutes
rate_key = f"otp_rate_limit:{identifier}"
logger.info(f"Checking rate limit with key: {rate_key}")
attempts = await redis.incr(rate_key)
logger.info(f"Current OTP attempts for {identifier}: {attempts}")
if attempts == 1:
await redis.expire(rate_key, BookMyServiceOTPModel.RATE_LIMIT_WINDOW)
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.")
# IP-based rate limiting
if client_ip:
ip_rate_key = f"otp_ip_rate_limit:{client_ip}"
ip_attempts = await redis.incr(ip_rate_key)
if ip_attempts == 1:
await redis.expire(ip_rate_key, BookMyServiceOTPModel.IP_RATE_LIMIT_WINDOW)
elif ip_attempts > BookMyServiceOTPModel.IP_RATE_LIMIT_MAX:
logger.warning(f"IP rate limit exceeded for {client_ip}: {ip_attempts} attempts")
raise HTTPException(status_code=429, detail="Too many OTP requests from this IP address")
# 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:
sid = send_sms_otp(phone, otp)
print(f"OTP {otp} sent to {phone} via SMS. SID: {sid}")
except Exception as sms_error:
print(f"⚠️ SMS failed: {sms_error}")
if is_email(identifier):
try:
await send_email_otp(identifier, otp)
print(f"✅ OTP {otp} sent to {identifier} via email fallback.")
except Exception as email_error:
raise HTTPException(status_code=500, detail=f"SMS and email both failed: {email_error}")
else:
raise HTTPException(status_code=500, detail="SMS failed and no email fallback available.")
'''
@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.info(f"Provided OTP: {otp}")
try:
redis = await get_redis()
logger.info("Redis connection established for OTP verification")
# Check if account is locked
if await BookMyServiceOTPModel.is_account_locked(identifier):
logger.warning(f"Account locked for identifier: {identifier}")
raise HTTPException(status_code=423, detail="Account temporarily locked due to too many failed attempts")
key = f"bms_otp:{identifier}"
logger.info(f"Looking up OTP with key: {key}")
stored = await redis.get(key)
logger.info(f"Stored OTP value: {stored}")
if 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.info(f"OTP deleted from Redis after successful verification")
return True
else:
logger.warning(f"OTP mismatch for {identifier}: provided='{otp}' vs stored='{stored}'")
# Track failed attempt
await BookMyServiceOTPModel.track_failed_attempt(identifier, client_ip)
return False
else:
logger.warning(f"No OTP found in Redis for identifier: {identifier} with key: {key}")
# Track failed attempt for expired/non-existent OTP
await BookMyServiceOTPModel.track_failed_attempt(identifier, client_ip)
return False
except HTTPException as e:
logger.error(f"HTTP error verifying OTP for {identifier}: {e.status_code} - {e.detail}")
raise e
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):
redis = await get_redis()
key = f"bms_otp:{identifier}"
otp = await redis.get(key)
if otp:
return otp
raise HTTPException(status_code=404, detail="OTP not found or expired")
@staticmethod
async def track_failed_attempt(identifier: str, client_ip: str = None):
"""Track failed OTP verification attempts"""
logger.info(f"Tracking failed attempt for identifier: {identifier}, IP: {client_ip}")
try:
redis = await get_redis()
# Track failed attempts for identifier
failed_key = f"failed_otp:{identifier}"
attempts = await redis.incr(failed_key)
if attempts == 1:
await redis.expire(failed_key, BookMyServiceOTPModel.FAILED_ATTEMPTS_WINDOW)
# Lock account if too many failed attempts
if attempts >= BookMyServiceOTPModel.FAILED_ATTEMPTS_MAX:
await BookMyServiceOTPModel.lock_account(identifier)
logger.warning(f"Account locked for {identifier} after {attempts} failed attempts")
# Track IP-based failed attempts
if client_ip:
ip_failed_key = f"failed_otp_ip:{client_ip}"
ip_attempts = await redis.incr(ip_failed_key)
if ip_attempts == 1:
await redis.expire(ip_failed_key, BookMyServiceOTPModel.FAILED_ATTEMPTS_WINDOW)
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)
@staticmethod
async def clear_failed_attempts(identifier: str):
"""Clear failed attempts counter on successful verification"""
try:
redis = await get_redis()
failed_key = f"failed_otp:{identifier}"
await redis.delete(failed_key)
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)
@staticmethod
async def lock_account(identifier: str):
"""Lock account temporarily"""
try:
redis = await get_redis()
lock_key = f"account_locked:{identifier}"
await redis.setex(lock_key, BookMyServiceOTPModel.ACCOUNT_LOCK_DURATION, "locked")
logger.info(f"Account locked for {identifier} for {BookMyServiceOTPModel.ACCOUNT_LOCK_DURATION} seconds")
except Exception as e:
logger.error(f"Error locking account for {identifier}: {str(e)}", exc_info=True)
@staticmethod
async def is_account_locked(identifier: str) -> bool:
"""Check if account is currently locked"""
try:
redis = await get_redis()
lock_key = f"account_locked:{identifier}"
locked = await redis.get(lock_key)
return locked is not None
except Exception as e:
logger.error(f"Error checking account lock for {identifier}: {str(e)}", exc_info=True)
return False
@staticmethod
async def get_rate_limit_count(rate_key: str) -> int:
"""Get current rate limit count for a key"""
try:
redis = await get_redis()
count = await redis.get(rate_key)
return int(count) if count else 0
except Exception as e:
logger.error(f"Error getting rate limit count for {rate_key}: {str(e)}", exc_info=True)
return 0
@staticmethod
async def increment_rate_limit(rate_key: str, window: int) -> int:
"""Increment rate limit counter with expiry"""
try:
redis = await get_redis()
count = await redis.incr(rate_key)
if count == 1:
await redis.expire(rate_key, window)
return count
except Exception as e:
logger.error(f"Error incrementing rate limit for {rate_key}: {str(e)}", exc_info=True)
return 0