debugging

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,

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"""

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():

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

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):

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"""