Add timing logs to auth dependency chain to identify 6s pre-handler delay

gns3server/api/routes/controller/dependencies/authentication.py

@@ -41,6 +41,10 @@ async def get_user_from_token(
         token: Optional[str] = Query(None, include_in_schema=False)
 ) -> schemas.User:
 
+    import time
+    _t0 = time.time()
+    log.info(f"[CTRL-TIMING] get_user_from_token ENTER bearer={bool(bearer_token)}")
+
     if bearer_token:
         # bearer token is used first, then any token passed as a URL parameter
         token = bearer_token
@@ -89,6 +93,7 @@ async def get_user_from_token(
             detail=f"Token has been revoked for '{token_data.username}'",
             headers={"WWW-Authenticate": "Bearer"},
         )
+    log.info(f"[CTRL-TIMING] get_user_from_token DONE elapsed={time.time()-_t0:.3f}s user={user.username}")
     return user
 
 

gns3server/api/routes/controller/dependencies/database.py

@@ -21,11 +21,19 @@ from sqlalchemy.ext.asyncio import AsyncSession
 
 from gns3server.db.repositories.base import BaseRepository
 
+import logging
+
+log = logging.getLogger(__name__)
+
 
 async def get_db_session(request: HTTPConnection) -> AsyncSession:
 
+    import time
+    _t0 = time.time()
+    log.info(f"[CTRL-TIMING] get_db_session ENTER")
     async with AsyncSession(request.app.state._db_engine, expire_on_commit=False) as session:
         try:
+            log.info(f"[CTRL-TIMING] get_db_session SESSION_READY elapsed={time.time()-_t0:.3f}s")
             yield session
         finally:
             await session.close()