Merge branch 'main' into rb/debug-session-issue

openhands/server/github.py

@@ -1,4 +1,5 @@
 import os
+import time
 
 from github import Github
 from github.GithubException import GithubException
@@ -14,7 +15,7 @@ GITHUB_CLIENT_SECRET = os.getenv('GITHUB_CLIENT_SECRET', '').strip()
 
 class UserVerifier:
     def __init__(self) -> None:
-        logger.debug('Initializing UserVerifier')
+        logger.info('Initializing UserVerifier')
         self.file_users: list[str] | None = None
         self.sheets_client: GoogleSheetsClient | None = None
         self.spreadsheet_id: str | None = None
@@ -27,7 +28,7 @@ class UserVerifier:
         """Load users from text file if configured"""
         waitlist = os.getenv('GITHUB_USER_LIST_FILE')
         if not waitlist:
-            logger.debug('GITHUB_USER_LIST_FILE not configured')
+            logger.info('GITHUB_USER_LIST_FILE not configured')
             return
 
         if not os.path.exists(waitlist):
@@ -48,10 +49,10 @@ class UserVerifier:
         sheet_id = os.getenv('GITHUB_USERS_SHEET_ID')
 
         if not sheet_id:
-            logger.debug('GITHUB_USERS_SHEET_ID not configured')
+            logger.info('GITHUB_USERS_SHEET_ID not configured')
             return
 
-        logger.debug('Initializing Google Sheets integration')
+        logger.info('Initializing Google Sheets integration')
         self.sheets_client = GoogleSheetsClient()
         self.spreadsheet_id = sheet_id
 
@@ -60,41 +61,50 @@ class UserVerifier:
 
     def is_user_allowed(self, username: str) -> bool:
         """Check if user is allowed based on file and/or sheet configuration"""
+        start_time = time.time()
         if not self.is_active():
             return True
 
-        logger.debug(f'Checking if GitHub user {username} is allowed')
+        logger.info(f'Checking if GitHub user {username} is allowed')
         if self.file_users:
             if username in self.file_users:
-                logger.debug(f'User {username} found in text file allowlist')
+                logger.info(f'User {username} found in text file allowlist')
                 return True
-            logger.debug(f'User {username} not found in text file allowlist')
+            logger.info(f'User {username} not found in text file allowlist')
+
+        logger.info(f'Took {time.time() - start_time:.2f} seconds to check file users')
 
         if self.sheets_client and self.spreadsheet_id:
             sheet_users = self.sheets_client.get_usernames(self.spreadsheet_id)
             if username in sheet_users:
-                logger.debug(f'User {username} found in Google Sheets allowlist')
+                logger.info(f'User {username} found in Google Sheets allowlist')
                 return True
-            logger.debug(f'User {username} not found in Google Sheets allowlist')
+            logger.info(f'User {username} not found in Google Sheets allowlist')
 
-        logger.debug(f'User {username} not found in any allowlist')
+        logger.info(f'Took {time.time() - start_time:.2f} seconds to check sheet users')
+
+        logger.info(f'User {username} not found in any allowlist')
         return False
 
 
 async def authenticate_github_user(auth_token) -> bool:
     user_verifier = UserVerifier()
+    logger.info('Initialized user verifier')
 
     if not user_verifier.is_active():
-        logger.debug('No user verification sources configured - allowing all users')
+        logger.info('No user verification sources configured - allowing all users')
         return True
 
-    logger.debug('Checking GitHub token')
+    logger.info('Checking GitHub token')
 
     if not auth_token:
         logger.warning('No GitHub token provided')
         return False
 
+    start_time = time.time()
+    logger.info('Getting GitHub user from token')
     login = await get_github_user(auth_token)
+    logger.info(f'Took {time.time() - start_time:.2f} seconds to get GitHub user')
 
     if not user_verifier.is_user_allowed(login):
         logger.warning(f'GitHub user {login} not in allow list')
@@ -114,7 +124,7 @@ async def get_github_user(token: str) -> str:
     Returns:
         github handle of the user
     """
-    logger.debug('Fetching GitHub user info from token')
+    logger.info('Fetching GitHub user info from token')
     try:
         g = Github(token)
         user = await call_sync_from_async(g.get_user)

openhands/server/listen.py

@@ -183,6 +183,8 @@ async def attach_session(request: Request, call_next):
     Returns:
         Response: The response from the next middleware or route handler.
     """
+    logger.info(f'Attaching session for {request.url.path}')
+    start_time = time.time()
     non_authed_paths = [
         '/api/options/',
         '/api/github/callback',
@@ -238,6 +240,8 @@ async def attach_session(request: Request, call_next):
     request.state.conversation = await session_manager.attach_to_conversation(
         request.state.sid
     )
+    end_time = time.time()
+    logger.info(f'Attach session time: {end_time - start_time:.2f}s')
     if request.state.conversation is None:
         return JSONResponse(
             status_code=status.HTTP_404_NOT_FOUND,
@@ -486,9 +490,12 @@ async def list_files(request: Request, path: str | None = None):
             status_code=status.HTTP_404_NOT_FOUND,
             content={'error': 'Runtime not yet initialized'},
         )
+    start_time = time.time()
 
     runtime: Runtime = request.state.conversation.runtime
     file_list = await call_sync_from_async(runtime.list_files, path)
+    end_time = time.time()
+    logger.info(f'List files time: {end_time - start_time:.2f}s')
     if path:
         file_list = [os.path.join(path, f) for f in file_list]
 
@@ -509,6 +516,8 @@ async def list_files(request: Request, path: str | None = None):
         return file_list
 
     file_list = await filter_for_gitignore(file_list, '')
+    end_time = time.time()
+    logger.info(f'Filter files time: {end_time - start_time:.2f}s')
 
     return file_list
 
@@ -862,12 +871,15 @@ def github_callback(auth_code: AuthCode):
 
 @app.post('/api/authenticate')
 async def authenticate(request: Request):
+    logger.info('Authenticating user via GitHub waitlist')
     token = request.headers.get('X-GitHub-Token')
     if not await authenticate_github_user(token):
+        logger.warning('User not authorized via GitHub waitlist')
         return JSONResponse(
             status_code=status.HTTP_401_UNAUTHORIZED,
             content={'error': 'Not authorized via GitHub waitlist'},
         )
+    logger.info('User authenticated via GitHub waitlist')
 
     # Create a signed JWT token with 1-hour expiration
     cookie_data = {