aljaz/enclava
1
0
Fork 0
mirror of https://github.com/aljazceru/enclava.git synced 2025-12-17 07:24:34 +01:00
Code Issues Packages Projects Releases Wiki Activity

more logging

Browse Source
This commit is contained in:
Aljaz Ceru
2025-09-18 13:17:18 +02:00
parent 3c30d55df9
commit 0a08690c7a
2 changed files with 104 additions and 65 deletions
Download Patch File Download Diff File Expand all files Collapse all files

117
backend/app/api/v1/auth.py
View File

@@ -1,7 +1,6 @@
""" """Authentication API endpoints"""
Authentication API endpoints
"""
import asyncio
import logging import logging
from datetime import datetime, timedelta from datetime import datetime, timedelta
from typing import Optional from typing import Optional
@@ -13,6 +12,7 @@ from sqlalchemy.ext.asyncio import AsyncSession
from sqlalchemy import select from sqlalchemy import select
from app.core.config import settings from app.core.config import settings
from app.core.logging import get_logger
from app.core.security import ( from app.core.security import (
verify_password, verify_password,
get_password_hash, get_password_hash,
@@ -26,7 +26,7 @@ from app.db.database import get_db
from app.models.user import User from app.models.user import User
from app.utils.exceptions import AuthenticationError, ValidationError from app.utils.exceptions import AuthenticationError, ValidationError
logger = logging.getLogger(__name__) logger = get_logger(__name__)
router = APIRouter() router = APIRouter()
security = HTTPBearer() security = HTTPBearer()
@@ -162,41 +162,59 @@ async def login(
): ):
"""Login user and return access tokens""" """Login user and return access tokens"""
logger.info(f"==================================================") logger.info(
logger.info(f"=== LOGIN ENDPOINT REACHED ===") "LOGIN_DEBUG_START",
logger.info(f"==================================================") request_time=datetime.utcnow().isoformat(),
logger.info(f"=== LOGIN DEBUG ===") email=user_data.email,
logger.info(f"Login attempt for email: {user_data.email}") database_url="SET" if settings.DATABASE_URL else "NOT SET",
logger.info(f"Current UTC time: {datetime.utcnow().isoformat()}") jwt_secret="SET" if settings.JWT_SECRET else "NOT SET",
logger.info(f"Settings check - DATABASE_URL: {'SET' if settings.DATABASE_URL else 'NOT SET'}") admin_email=settings.ADMIN_EMAIL,
logger.info(f"Settings check - JWT_SECRET: {'SET' if settings.JWT_SECRET else 'NOT SET'}") bcrypt_rounds=settings.BCRYPT_ROUNDS,
logger.info(f"Settings check - ADMIN_EMAIL: {settings.ADMIN_EMAIL}") )
logger.info(f"Settings check - BCRYPT_ROUNDS: {settings.BCRYPT_ROUNDS}")
# DEBUG: Check Redis connection # DEBUG: Check Redis connection (keep lightweight to avoid request stalls)
if settings.APP_DEBUG:
try: try:
logger.info("Testing Redis connection...") logger.info("LOGIN_REDIS_CHECK_START", redis_url=redis_url)
import redis.asyncio as redis import redis.asyncio as redis
redis_url = settings.REDIS_URL redis_url = settings.REDIS_URL
logger.info(f"Redis URL: {redis_url}") logger.info(f"Redis URL: {redis_url}")
redis_client = redis.from_url(redis_url) redis_client = redis.from_url(
redis_url,
socket_connect_timeout=1.0,
socket_timeout=1.0,
)
test_start = datetime.utcnow() test_start = datetime.utcnow()
await redis_client.ping() try:
await asyncio.wait_for(redis_client.ping(), timeout=1.5)
test_end = datetime.utcnow() test_end = datetime.utcnow()
logger.info(f"Redis connection test successful. Time: {(test_end - test_start).total_seconds()} seconds") logger.info(
"LOGIN_REDIS_CHECK_SUCCESS",
duration_seconds=(test_end - test_start).total_seconds(),
)
except asyncio.TimeoutError:
logger.warning("LOGIN_REDIS_CHECK_TIMEOUT", timeout_seconds=1.5)
finally:
await redis_client.close() await redis_client.close()
except Exception as e: except Exception as e:
logger.error(f"Redis connection test failed: {e}") logger.error("LOGIN_REDIS_CHECK_FAILURE", error=str(e))
# DEBUG: Check database connection with timeout # DEBUG: Check database connection with timeout
if settings.APP_DEBUG:
try: try:
logger.info("Testing database connection...") logger.info("LOGIN_DB_PING_START")
test_start = datetime.utcnow() test_start = datetime.utcnow()
await db.execute(select(1)) await asyncio.wait_for(db.execute(select(1)), timeout=3.0)
test_end = datetime.utcnow() test_end = datetime.utcnow()
logger.info(f"Database connection test successful. Time: {(test_end - test_start).total_seconds()} seconds") logger.info(
"LOGIN_DB_PING_SUCCESS",
duration_seconds=(test_end - test_start).total_seconds(),
)
except asyncio.TimeoutError:
logger.warning("LOGIN_DB_PING_TIMEOUT", timeout_seconds=3.0)
except Exception as e: except Exception as e:
logger.error(f"Database connection test failed: {e}") logger.error("LOGIN_DB_PING_FAILURE", error=str(e))
raise HTTPException( raise HTTPException(
status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
detail="Database connection error" detail="Database connection error"
@@ -205,45 +223,57 @@ async def login(
start_time = datetime.utcnow() start_time = datetime.utcnow()
# Get user by email # Get user by email
logger.info("Querying user by email...") logger.info("LOGIN_USER_QUERY_START")
query_start = datetime.utcnow() query_start = datetime.utcnow()
stmt = select(User).where(User.email == user_data.email) stmt = select(User).where(User.email == user_data.email)
result = await db.execute(stmt) result = await db.execute(stmt)
query_end = datetime.utcnow() query_end = datetime.utcnow()
logger.info(f"User query completed. Time: {(query_end - query_start).total_seconds()} seconds") logger.info(
"LOGIN_USER_QUERY_END",
duration_seconds=(query_end - query_start).total_seconds(),
)
user = result.scalar_one_or_none() user = result.scalar_one_or_none()
if not user: if not user:
logger.warning(f"User not found: {user_data.email}") logger.warning("LOGIN_USER_NOT_FOUND", email=user_data.email)
# List available users for debugging # List available users for debugging
try: try:
all_users_stmt = select(User).limit(5) all_users_stmt = select(User).limit(5)
all_users_result = await db.execute(all_users_stmt) all_users_result = await db.execute(all_users_stmt)
all_users = all_users_result.scalars().all() all_users = all_users_result.scalars().all()
logger.info(f"Available users (first 5): {[u.email for u in all_users]}") logger.info(
"LOGIN_USER_LIST",
users=[u.email for u in all_users],
)
except Exception as e: except Exception as e:
logger.error(f"Could not list users: {e}") logger.error("LOGIN_USER_LIST_FAILURE", error=str(e))
raise HTTPException( raise HTTPException(
status_code=status.HTTP_401_UNAUTHORIZED, status_code=status.HTTP_401_UNAUTHORIZED,
detail="Incorrect email or password" detail="Incorrect email or password"
) )
logger.info(f"User found: {user.email}, is_active: {user.is_active}") logger.info("LOGIN_USER_FOUND", email=user.email, is_active=user.is_active)
logger.info(f"User found, starting password verification...") logger.info("LOGIN_PASSWORD_VERIFY_START")
verify_start = datetime.utcnow() verify_start = datetime.utcnow()
if not verify_password(user_data.password, user.hashed_password): if not verify_password(user_data.password, user.hashed_password):
verify_end = datetime.utcnow() verify_end = datetime.utcnow()
logger.warning(f"Password verification failed. Time taken: {(verify_end - verify_start).total_seconds()} seconds") logger.warning(
"LOGIN_PASSWORD_VERIFY_FAILURE",
duration_seconds=(verify_end - verify_start).total_seconds(),
)
raise HTTPException( raise HTTPException(
status_code=status.HTTP_401_UNAUTHORIZED, status_code=status.HTTP_401_UNAUTHORIZED,
detail="Incorrect email or password" detail="Incorrect email or password"
) )
verify_end = datetime.utcnow() verify_end = datetime.utcnow()
logger.info(f"Password verification successful. Time taken: {(verify_end - verify_start).total_seconds()} seconds") logger.info(
"LOGIN_PASSWORD_VERIFY_SUCCESS",
duration_seconds=(verify_end - verify_start).total_seconds(),
)
if not user.is_active: if not user.is_active:
raise HTTPException( raise HTTPException(
@@ -252,19 +282,20 @@ async def login(
) )
# Update last login # Update last login
logger.info("Updating last login...") logger.info("LOGIN_LAST_LOGIN_UPDATE_START")
update_start = datetime.utcnow() update_start = datetime.utcnow()
user.update_last_login() user.update_last_login()
await db.commit() await db.commit()
update_end = datetime.utcnow() update_end = datetime.utcnow()
logger.info(f"Last login updated. Time: {(update_end - update_start).total_seconds()} seconds") logger.info(
"LOGIN_LAST_LOGIN_UPDATE_SUCCESS",
duration_seconds=(update_end - update_start).total_seconds(),
)
# Create tokens # Create tokens
logger.info("Creating tokens...") logger.info("LOGIN_TOKEN_CREATE_START")
token_start = datetime.utcnow() token_start = datetime.utcnow()
access_token_expires = timedelta(minutes=settings.ACCESS_TOKEN_EXPIRE_MINUTES) access_token_expires = timedelta(minutes=settings.ACCESS_TOKEN_EXPIRE_MINUTES)
logger.info(f"Creating access token with expiration: {access_token_expires}")
logger.info(f"ACCESS_TOKEN_EXPIRE_MINUTES from settings: {settings.ACCESS_TOKEN_EXPIRE_MINUTES}")
access_token = create_access_token( access_token = create_access_token(
data={ data={
@@ -280,10 +311,16 @@ async def login(
data={"sub": str(user.id), "type": "refresh"} data={"sub": str(user.id), "type": "refresh"}
) )
token_end = datetime.utcnow() token_end = datetime.utcnow()
logger.info(f"Tokens created. Time: {(token_end - token_start).total_seconds()} seconds") logger.info(
"LOGIN_TOKEN_CREATE_SUCCESS",
duration_seconds=(token_end - token_start).total_seconds(),
)
total_time = datetime.utcnow() - start_time total_time = datetime.utcnow() - start_time
logger.info(f"=== LOGIN COMPLETED === Total time: {total_time.total_seconds()} seconds") logger.info(
"LOGIN_DEBUG_COMPLETE",
total_duration_seconds=total_time.total_seconds(),
)
return TokenResponse( return TokenResponse(
access_token=access_token, access_token=access_token,

2
backend/app/db/database.py
View File

@@ -24,6 +24,7 @@ engine = create_async_engine(
pool_recycle=3600, # Recycle connections every hour pool_recycle=3600, # Recycle connections every hour
pool_timeout=30, # Max time to get connection from pool pool_timeout=30, # Max time to get connection from pool
connect_args={ connect_args={
"timeout": 5,
"command_timeout": 5, "command_timeout": 5,
"server_settings": { "server_settings": {
"application_name": "enclava_backend", "application_name": "enclava_backend",
@@ -49,6 +50,7 @@ sync_engine = create_engine(
pool_recycle=3600, # Recycle connections every hour pool_recycle=3600, # Recycle connections every hour
pool_timeout=30, # Max time to get connection from pool pool_timeout=30, # Max time to get connection from pool
connect_args={ connect_args={
"connect_timeout": 5,
"application_name": "enclava_backend_sync", "application_name": "enclava_backend_sync",
}, },
) )