From 9d3da204013e7a3950f81bf277f2e495d7984493 Mon Sep 17 00:00:00 2001 From: Aljaz Ceru Date: Thu, 18 Sep 2025 11:42:18 +0200 Subject: [PATCH] debugging --- backend/app/api/v1/auth.py | 50 ++++++++++++++++ backend/app/core/security.py | 70 +++++++++++++++++----- backend/app/db/database.py | 38 ++++++++---- backend/app/main.py | 8 +++ backend/app/middleware/debugging.py | 3 + backend/app/services/permission_manager.py | 41 +++++++++---- 6 files changed, 171 insertions(+), 39 deletions(-) diff --git a/backend/app/api/v1/auth.py b/backend/app/api/v1/auth.py index 8782989..5e3bbb5 100644 --- a/backend/app/api/v1/auth.py +++ b/backend/app/api/v1/auth.py @@ -2,6 +2,7 @@ Authentication API endpoints """ +import logging from datetime import datetime, timedelta from typing import Optional @@ -25,6 +26,8 @@ from app.db.database import get_db from app.models.user import User from app.utils.exceptions import AuthenticationError, ValidationError +logger = logging.getLogger(__name__) + router = APIRouter() security = HTTPBearer() @@ -159,21 +162,57 @@ async def login( ): """Login user and return access tokens""" + logger.info(f"=== LOGIN DEBUG ===") logger.info(f"Login attempt for email: {user_data.email}") + logger.info(f"Current UTC time: {datetime.utcnow().isoformat()}") + logger.info(f"Settings check - DATABASE_URL: {'SET' if settings.DATABASE_URL else 'NOT SET'}") + logger.info(f"Settings check - JWT_SECRET: {'SET' if settings.JWT_SECRET else 'NOT SET'}") + logger.info(f"Settings check - ADMIN_EMAIL: {settings.ADMIN_EMAIL}") + logger.info(f"Settings check - BCRYPT_ROUNDS: {settings.BCRYPT_ROUNDS}") + + # DEBUG: Check database connection with timeout + try: + logger.info("Testing database connection...") + test_start = datetime.utcnow() + await db.execute(select(1)) + test_end = datetime.utcnow() + logger.info(f"Database connection test successful. Time: {(test_end - test_start).total_seconds()} seconds") + except Exception as e: + logger.error(f"Database connection test failed: {e}") + raise HTTPException( + status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, + detail="Database connection error" + ) + start_time = datetime.utcnow() # Get user by email + logger.info("Querying user by email...") + query_start = datetime.utcnow() stmt = select(User).where(User.email == user_data.email) result = await db.execute(stmt) + query_end = datetime.utcnow() + logger.info(f"User query completed. Time: {(query_end - query_start).total_seconds()} seconds") + user = result.scalar_one_or_none() if not user: logger.warning(f"User not found: {user_data.email}") + # List available users for debugging + try: + all_users_stmt = select(User).limit(5) + all_users_result = await db.execute(all_users_stmt) + all_users = all_users_result.scalars().all() + logger.info(f"Available users (first 5): {[u.email for u in all_users]}") + except Exception as e: + logger.error(f"Could not list users: {e}") + raise HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail="Incorrect email or password" ) + logger.info(f"User found: {user.email}, is_active: {user.is_active}") logger.info(f"User found, starting password verification...") verify_start = datetime.utcnow() @@ -195,10 +234,16 @@ async def login( ) # Update last login + logger.info("Updating last login...") + update_start = datetime.utcnow() user.update_last_login() await db.commit() + update_end = datetime.utcnow() + logger.info(f"Last login updated. Time: {(update_end - update_start).total_seconds()} seconds") # Create tokens + logger.info("Creating tokens...") + token_start = datetime.utcnow() 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}") @@ -216,6 +261,11 @@ async def login( refresh_token = create_refresh_token( data={"sub": str(user.id), "type": "refresh"} ) + token_end = datetime.utcnow() + logger.info(f"Tokens created. Time: {(token_end - token_start).total_seconds()} seconds") + + total_time = datetime.utcnow() - start_time + logger.info(f"=== LOGIN COMPLETED === Total time: {total_time.total_seconds()} seconds") return TokenResponse( access_token=access_token, diff --git a/backend/app/core/security.py b/backend/app/core/security.py index 6611fe0..b5a3373 100644 --- a/backend/app/core/security.py +++ b/backend/app/core/security.py @@ -32,7 +32,25 @@ security = HTTPBearer() def verify_password(plain_password: str, hashed_password: str) -> bool: """Verify a password against its hash""" - return pwd_context.verify(plain_password, hashed_password) + import time + start_time = time.time() + logger.info(f"=== PASSWORD VERIFICATION START === BCRYPT_ROUNDS: {settings.BCRYPT_ROUNDS}") + + try: + result = pwd_context.verify(plain_password, hashed_password) + end_time = time.time() + duration = end_time - start_time + logger.info(f"=== PASSWORD VERIFICATION END === Duration: {duration:.3f}s, Result: {result}") + + if duration > 5: + logger.warning(f"PASSWORD VERIFICATION TOOK TOO LONG: {duration:.3f}s") + + return result + except Exception as e: + end_time = time.time() + duration = end_time - start_time + logger.error(f"=== PASSWORD VERIFICATION FAILED === Duration: {duration:.3f}s, Error: {e}") + raise def get_password_hash(password: str) -> str: """Generate password hash""" @@ -48,22 +66,42 @@ def get_api_key_hash(api_key: str) -> str: def create_access_token(data: Dict[str, Any], expires_delta: Optional[timedelta] = None) -> str: """Create JWT access token""" - to_encode = data.copy() - if expires_delta: - expire = datetime.utcnow() + expires_delta - else: - expire = datetime.utcnow() + timedelta(minutes=settings.ACCESS_TOKEN_EXPIRE_MINUTES) + import time + start_time = time.time() + logger.info(f"=== CREATE ACCESS TOKEN START ===") - to_encode.update({"exp": expire}) - encoded_jwt = jwt.encode(to_encode, settings.JWT_SECRET, algorithm=settings.JWT_ALGORITHM) - - # Log token creation details - logger.info(f"Created access token for user {data.get('sub')}") - logger.info(f"Token expires at: {expire.isoformat()} (UTC)") - logger.info(f"Current UTC time: {datetime.utcnow().isoformat()}") - logger.info(f"ACCESS_TOKEN_EXPIRE_MINUTES setting: {settings.ACCESS_TOKEN_EXPIRE_MINUTES}") - - return encoded_jwt + try: + to_encode = data.copy() + if expires_delta: + expire = datetime.utcnow() + expires_delta + else: + expire = datetime.utcnow() + timedelta(minutes=settings.ACCESS_TOKEN_EXPIRE_MINUTES) + + to_encode.update({"exp": expire}) + logger.info(f"JWT encode start...") + encode_start = time.time() + encoded_jwt = jwt.encode(to_encode, settings.JWT_SECRET, algorithm=settings.JWT_ALGORITHM) + encode_end = time.time() + encode_duration = encode_end - encode_start + + end_time = time.time() + total_duration = end_time - start_time + + # Log token creation details + logger.info(f"Created access token for user {data.get('sub')}") + logger.info(f"Token expires at: {expire.isoformat()} (UTC)") + logger.info(f"Current UTC time: {datetime.utcnow().isoformat()}") + logger.info(f"ACCESS_TOKEN_EXPIRE_MINUTES setting: {settings.ACCESS_TOKEN_EXPIRE_MINUTES}") + logger.info(f"JWT encode duration: {encode_duration:.3f}s") + logger.info(f"Total token creation duration: {total_duration:.3f}s") + logger.info(f"=== CREATE ACCESS TOKEN END ===") + + return encoded_jwt + except Exception as e: + end_time = time.time() + total_duration = end_time - start_time + logger.error(f"=== CREATE ACCESS TOKEN FAILED === Duration: {total_duration:.3f}s, Error: {e}") + raise def create_refresh_token(data: Dict[str, Any]) -> str: """Create JWT refresh token""" diff --git a/backend/app/db/database.py b/backend/app/db/database.py index 9b05c5e..3c51fcc 100644 --- a/backend/app/db/database.py +++ b/backend/app/db/database.py @@ -68,17 +68,33 @@ metadata = MetaData() async def get_db() -> AsyncGenerator[AsyncSession, None]: """Get database session""" - async with async_session_factory() as session: - try: - yield session - except Exception as e: - # Only log if there's an actual error, not normal operation - if str(e).strip(): # Only log if error message exists - logger.error(f"Database session error: {str(e)}", exc_info=True) - await session.rollback() - raise - finally: - await session.close() + import time + start_time = time.time() + request_id = f"db_{int(time.time() * 1000)}" + + logger.info(f"[{request_id}] === DATABASE SESSION START ===") + + try: + logger.info(f"[{request_id}] Creating database session...") + async with async_session_factory() as session: + logger.info(f"[{request_id}] Database session created successfully") + try: + yield session + except Exception as e: + # Only log if there's an actual error, not normal operation + if str(e).strip(): # Only log if error message exists + logger.error(f"[{request_id}] Database session error: {str(e)}", exc_info=True) + await session.rollback() + raise + finally: + close_start = time.time() + await session.close() + close_time = time.time() - close_start + total_time = time.time() - start_time + logger.info(f"[{request_id}] Database session closed. Close time: {close_time:.3f}s, Total time: {total_time:.3f}s") + except Exception as e: + logger.error(f"[{request_id}] Failed to create database session: {e}", exc_info=True) + raise async def init_db(): diff --git a/backend/app/main.py b/backend/app/main.py index 5e5eefa..95d1753 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -57,8 +57,16 @@ async def lifespan(app: FastAPI): init_analytics_service() # Initialize module manager with FastAPI app for router registration + logger.info("Initializing module manager...") await module_manager.initialize(app) app.state.module_manager = module_manager + logger.info("Module manager initialized successfully") + + # Initialize permission registry + logger.info("Initializing permission registry...") + from app.services.permission_manager import permission_registry + permission_registry.register_platform_permissions() + logger.info("Permission registry initialized successfully") # Initialize document processor from app.services.document_processor import document_processor diff --git a/backend/app/middleware/debugging.py b/backend/app/middleware/debugging.py index 2d24a1e..ca2dd29 100644 --- a/backend/app/middleware/debugging.py +++ b/backend/app/middleware/debugging.py @@ -71,8 +71,11 @@ class DebuggingMiddleware(BaseHTTPMiddleware): response = None response_body = None + # Add timeout detection try: + logger.info(f"=== START PROCESSING REQUEST === {request_id} at {datetime.utcnow().isoformat()}") response = await call_next(request) + logger.info(f"=== REQUEST COMPLETED === {request_id} at {datetime.utcnow().isoformat()}") # Capture response body for successful JSON responses if response.status_code < 400 and isinstance(response, JSONResponse): diff --git a/backend/app/services/permission_manager.py b/backend/app/services/permission_manager.py index 9c96923..4f10b92 100644 --- a/backend/app/services/permission_manager.py +++ b/backend/app/services/permission_manager.py @@ -266,21 +266,38 @@ class ModulePermissionRegistry: return True - def get_user_permissions(self, roles: List[str], + def get_user_permissions(self, roles: List[str], custom_permissions: List[str] = None) -> List[str]: """Get effective permissions for a user based on roles and custom permissions""" - permissions = set() + import time + start_time = time.time() + logger.info(f"=== GET USER PERMISSIONS START === Roles: {roles}, Custom perms: {custom_permissions}") - # Add role-based permissions - for role in roles: - role_perms = self.role_permissions.get(role, self.default_roles.get(role, [])) - permissions.update(role_perms) - - # Add custom permissions - if custom_permissions: - permissions.update(custom_permissions) - - return list(permissions) + try: + permissions = set() + + # Add role-based permissions + for role in roles: + role_perms = self.role_permissions.get(role, self.default_roles.get(role, [])) + logger.info(f"Role '{role}' has {len(role_perms)} permissions") + permissions.update(role_perms) + + # Add custom permissions + if custom_permissions: + permissions.update(custom_permissions) + logger.info(f"Added {len(custom_permissions)} custom permissions") + + result = list(permissions) + end_time = time.time() + duration = end_time - start_time + logger.info(f"=== GET USER PERMISSIONS END === Total permissions: {len(result)}, Duration: {duration:.3f}s") + + return result + except Exception as e: + end_time = time.time() + duration = end_time - start_time + logger.error(f"=== GET USER PERMISSIONS FAILED === Duration: {duration:.3f}s, Error: {e}") + raise def get_module_permissions(self, module_id: str) -> List[Permission]: """Get all permissions for a specific module"""