diff --git a/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py b/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py index a0c891c8a..fb260a286 100644 --- a/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py +++ b/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py @@ -49,7 +49,6 @@ Upstream: https://github.com/davidban77/gns3fy import os import time -import logging from collections.abc import Callable from dataclasses import field from functools import wraps @@ -76,7 +75,6 @@ F = TypeVar("F", bound=Callable[..., Any]) config = ConfigDict(validate_assignment=True, extra="ignore") -log = logging.getLogger(__name__) NODE_TYPES = [ "cloud", @@ -214,9 +212,6 @@ class Gns3Connector: Performs v3 API authentication using username and password to get JWT token. Skips authentication if a JWT token is already provided. """ - import time - _t0 = time.time() - log.info(f"[MCP-TIMING] _authenticate_v3 ENTER has_token={bool(self.access_token)}") # If token is already provided, skip authentication if self.access_token: return @@ -255,9 +250,7 @@ class Gns3Connector: f"{response.text}" ) except Exception as e: - log.error(f"[MCP-TIMING] _authenticate_v3 FAIL elapsed={time.time()-_t0:.3f}s error={e}") raise HTTPError(f"v3 API authentication error: {str(e)}") from e - log.info(f"[MCP-TIMING] _authenticate_v3 DONE elapsed={time.time()-_t0:.3f}s") def _is_token_expired(self) -> bool: """ @@ -299,9 +292,6 @@ class Gns3Connector: """ Executes HTTP operations and handles GNS3-specific error logic. """ - import time - _t0 = time.time() - log.info(f"[MCP-TIMING] http_call ENTER {method.upper()} {url.split('/v3')[1] if '/v3' in url else url}") # Handle JWT authentication if ( @@ -311,7 +301,6 @@ class Gns3Connector: and self.cred ): self._authenticate_v3() - log.info(f"[MCP-TIMING] http_call auth done elapsed={time.time()-_t0:.3f}s") # Get request function (e.g., session.get, session.post) caller = getattr(self.session, method.lower()) @@ -333,12 +322,10 @@ class Gns3Connector: self.api_calls += 1 - log.info(f"[MCP-TIMING] http_call RESPONSE elapsed={time.time()-_t0:.3f}s status={_response.status_code}") try: _response.raise_for_status() except HTTPError as e: - log.error(f"[MCP-TIMING] http_call ERROR elapsed={time.time()-_t0:.3f}s {e}") # Throw enhanced error raise self._extract_gns3_error(e) from e diff --git a/gns3server/api/routes/controller/dependencies/authentication.py b/gns3server/api/routes/controller/dependencies/authentication.py index cc041429a..b6332edbf 100644 --- a/gns3server/api/routes/controller/dependencies/authentication.py +++ b/gns3server/api/routes/controller/dependencies/authentication.py @@ -45,7 +45,6 @@ async def get_user_from_token( 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 @@ -61,7 +60,6 @@ async def get_user_from_token( # API Key authentication — format: gns3__ # Direct lookup by UUID avoids O(n) scan of all keys. if token.startswith("gns3_"): - log.info(f"[CTRL-TIMING] get_user_from_token API_KEY auth elapsed={time.time()-_t0:.3f}s") parts = token.split("_", 2) if len(parts) != 3: raise HTTPException(status_code=status.HTTP_401_UNAUTHORIZED, detail="Invalid API key format") @@ -100,7 +98,6 @@ 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 diff --git a/gns3server/api/routes/controller/dependencies/database.py b/gns3server/api/routes/controller/dependencies/database.py index e01e95349..bec80819e 100644 --- a/gns3server/api/routes/controller/dependencies/database.py +++ b/gns3server/api/routes/controller/dependencies/database.py @@ -30,10 +30,8 @@ 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() diff --git a/gns3server/api/routes/controller/projects.py b/gns3server/api/routes/controller/projects.py index eb3e7333e..3645394d1 100644 --- a/gns3server/api/routes/controller/projects.py +++ b/gns3server/api/routes/controller/projects.py @@ -609,12 +609,9 @@ async def create_node_from_template( Required privilege: Node.Allocate """ - import time as _time _t0 = _time.time() - log.info(f"[CTRL-TIMING] create_node_from_template ENTER template_id={template_id}") template = await TemplatesService(templates_repo).get_template(template_id) - log.info(f"[CTRL-TIMING] get_template done elapsed={_time.time()-_t0:.3f}s") controller = Controller.instance() project = controller.get_project(str(project_id)) @@ -622,8 +619,6 @@ async def create_node_from_template( node = await project.add_node_from_template( template, x=template_usage.x, y=template_usage.y, compute_id=template_usage.compute_id ) - log.info(f"[CTRL-TIMING] add_node_from_template done elapsed={_time.time()-_t0:.3f}s") result = node.asdict() - log.info(f"[CTRL-TIMING] create_node_from_template DONE total={_time.time()-_t0:.3f}s") return result diff --git a/gns3server/api/routes/mcp/nodes.py b/gns3server/api/routes/mcp/nodes.py index a2a48898c..cf5251284 100644 --- a/gns3server/api/routes/mcp/nodes.py +++ b/gns3server/api/routes/mcp/nodes.py @@ -205,7 +205,6 @@ def _filter_node_response(node: dict, fields: list[str] = None) -> dict: def create_node_handler(params: dict[str, Any], gns3_ctx: dict[str, Any]) -> dict[str, Any]: import time _t0 = time.time() - log.info(f"[MCP-TIMING] create_node_handler ENTER at T={_t0:.3f}") project_id = params.get("project_id") if not project_id: @@ -219,7 +218,6 @@ def create_node_handler(params: dict[str, Any], gns3_ctx: dict[str, Any]) -> dic if nodes is not None: if not isinstance(nodes, list) or not nodes: return {"error": "nodes must be a non-empty array"} - log.info(f"[MCP-TIMING] batch mode: {len(nodes)} nodes, handler_setup={time.time()-_t0:.3f}s") default_tid = params.get("template_id") results = [] conn = _get_connector(gns3_ctx) @@ -238,22 +236,17 @@ def create_node_handler(params: dict[str, Any], gns3_ctx: dict[str, Any]) -> dic node_name = node_data.get("name") if node_name: body["name"] = node_name - log.info(f"[MCP-TIMING] http_call START tid={tid} name={node_name} setup={time.time()-_t1:.3f}s") resp = conn.http_call("post", url, json_data=body).json() - log.info(f"[MCP-TIMING] http_call END tid={tid} elapsed={time.time()-_t1:.3f}s") return {"template_id": tid, "status": "success", "node": _filter_node_response(resp, fields)} except Exception as e: - log.error(f"[MCP-TIMING] http_call FAIL tid={tid} elapsed={time.time()-_t1:.3f}s error={e}") return {"template_id": tid, "status": "error", "error": str(e)} with ThreadPoolExecutor(max_workers=min(len(nodes), BATCH_MAX_WORKERS)) as pool: futures = {pool.submit(_create_one, n): n for n in nodes} for future in as_completed(futures): results.append(future.result()) - log.info(f"[MCP-TIMING] batch done: {len(results)} results, total={time.time()-_t0:.3f}s") return results # Single mode - log.info(f"[MCP-TIMING] single mode: handler_setup={time.time()-_t0:.3f}s") template_id = params.get("template_id") if not template_id: return {"error": "template_id is required"} @@ -268,9 +261,7 @@ def create_node_handler(params: dict[str, Any], gns3_ctx: dict[str, Any]) -> dic data["name"] = node_name url = f"{conn.base_url}/projects/{project_id}/templates/{template_id}" _t2 = time.time() - log.info(f"[MCP-TIMING] http_call START single template_id={template_id} setup={_t2-_t0:.3f}s") resp = conn.http_call("post", url, json_data=data).json() - log.info(f"[MCP-TIMING] http_call END single elapsed={time.time()-_t2:.3f}s, total={time.time()-_t0:.3f}s") return _filter_node_response(resp, fields) diff --git a/gns3server/api/server.py b/gns3server/api/server.py index 51449d8a9..7c32fb833 100644 --- a/gns3server/api/server.py +++ b/gns3server/api/server.py @@ -49,7 +49,6 @@ from gns3server.api.routes import mcp from gns3server.core import tasks import logging -import time log = logging.getLogger(__name__) @@ -215,23 +214,7 @@ async def validation_exception_handler(request: Request, exc: RequestValidationE content={"message": str(exc)} ) - @app.middleware("http") - async def timing_middleware(request: Request, call_next): - _t0 = time.time() - response = await call_next(request) - elapsed = time.time() - _t0 - if elapsed > 1.0: - log.info(f"[CTRL-TIMING] request {request.method} {request.url.path} total={elapsed:.3f}s") - return response # FIXME: do not use this middleware since it creates issue when using StreamingResponse # see https://starlette-context.readthedocs.io/en/latest/middleware.html#why-are-there-two-middlewares-that-do-the-same-thing -# @app.middleware("http") -# async def add_extra_headers(request: Request, call_next): -# start_time = time.time() -# response = await call_next(request) -# process_time = time.time() - start_time -# response.headers["X-Process-Time"] = str(process_time) -# response.headers["X-GNS3-Server-Version"] = f"{__version__}" -# return response diff --git a/gns3server/controller/compute.py b/gns3server/controller/compute.py index 87c32a551..c2da920bb 100644 --- a/gns3server/controller/compute.py +++ b/gns3server/controller/compute.py @@ -547,12 +547,9 @@ class Compute: data = json.dumps(data).encode("utf-8") try: log.debug(f"Attempting request to compute: {method} {url} {headers}") - _t0 = time.time() response = await self._session().request( method, url, headers=headers, data=data, auth=self._auth, params=params, chunked=chunked, timeout=timeout ) - log.info(f"[CTRL-TIMING] compute._session.request DONE {method} {url.split('/v3')[1] if '/v3' in url else url} " - f"status={response.status} elapsed={time.time()-_t0:.3f}s") except asyncio.TimeoutError: raise ComputeError(f"Timeout error for {method} call to {url} after {timeout}s") except ( diff --git a/gns3server/controller/node.py b/gns3server/controller/node.py index 44516e3dd..3378f055f 100644 --- a/gns3server/controller/node.py +++ b/gns3server/controller/node.py @@ -402,8 +402,6 @@ class Node: """ Create the node on the compute """ - import time as _time - _t0 = _time.time() data = self._node_data() data["node_id"] = self._id if self._node_type == "docker": @@ -416,8 +414,6 @@ class Node: response = await self._compute.post( f"/projects/{self._project.id}/{self._node_type}/nodes", data=data, timeout=timeout ) - log.info(f"[CTRL-TIMING] Node.create compute_post DONE name={self._name} " - f"type={self._node_type} elapsed={_time.time()-_t0:.3f}s") except ComputeConflictError as e: response = e.response() if response.get("exception") == "ImageMissingError": diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 2e27b02bf..bed55eb60 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -563,9 +563,6 @@ class Project: """ Create a node from a template. """ - import time as _time - _t0 = _time.time() - template["x"] = x template["y"] = y node_type = template.pop("template_type") @@ -581,15 +578,11 @@ class Project: name = default_name_format.replace("{name}", template_name) node_id = str(uuid.uuid4()) node = await self.add_node(compute, name, node_id, node_type=node_type, **template) - log.info(f"[CTRL-TIMING] add_node_from_template DONE name={name} elapsed={_time.time()-_t0:.3f}s") return node async def _create_node(self, compute, name, node_id, node_type=None, **kwargs): - import time as _time - _t0 = _time.time() node = Node(self, compute, name, node_id=node_id, node_type=node_type, **kwargs) - _t1 = _time.time() if compute not in self._project_created_on_compute: if compute.id == "local": data = {"name": self._name, "project_id": self._id, "path": self._path} @@ -599,12 +592,9 @@ class Project: data["variables"] = self._variables await compute.post("/projects", data=data) self._project_created_on_compute.add(compute) - log.info(f"[CTRL-TIMING] _create_node project_setup name={name} elapsed={_time.time()-_t0:.3f}s" - f" (node_init={_t1-_t0:.3f}s)") await node.create() self._nodes[node.id] = node - log.info(f"[CTRL-TIMING] _create_node node.create DONE name={name} elapsed={_time.time()-_t0:.3f}s") return node diff --git a/gns3server/db/repositories/templates.py b/gns3server/db/repositories/templates.py index 80d68a281..c141008d0 100644 --- a/gns3server/db/repositories/templates.py +++ b/gns3server/db/repositories/templates.py @@ -53,22 +53,12 @@ class TemplatesRepository(BaseRepository): super().__init__(db_session) async def get_template(self, template_id: UUID) -> Union[None, models.Template]: - import time - _t0 = time.time() query = select(models.Template).\ options(selectinload(models.Template.images)).\ where(models.Template.template_id == template_id) - _t1 = time.time() result = await self._db_session.execute(query) - _t2 = time.time() - row = result.scalars().first() - _t3 = time.time() - - if _t3 - _t0 > 0.1: - log.warning(f"[CTRL-TIMING] DB get_template SLOW template_id={template_id} " - f"execute={_t2-_t1:.3f}s fetch={_t3-_t2:.3f}s total={_t3-_t0:.3f}s") - return row + return result.scalars().first() async def get_template_by_name_and_version(self, name: str, version: str) -> Union[None, models.Template]: diff --git a/gns3server/services/templates.py b/gns3server/services/templates.py index cdd7ce9a4..a6c04d865 100644 --- a/gns3server/services/templates.py +++ b/gns3server/services/templates.py @@ -264,7 +264,6 @@ class TemplatesService: _t0 = time.time() db_template = await self._templates_repo.get_template(template_id) - log.info(f"[CTRL-TIMING] TemplatesService.get_template repo done elapsed={time.time()-_t0:.3f}s") if db_template: template = db_template.asjson() @@ -272,7 +271,6 @@ class TemplatesService: template = self.get_builtin_template(template_id) if not template: raise ControllerNotFoundError(f"Template '{template_id}' not found") - log.info(f"[CTRL-TIMING] TemplatesService.get_template DONE total={time.time()-_t0:.3f}s") return template async def _remove_image(self, template_id: UUID, image_path: str) -> None: