From cef6dc6bd20e10b61fcdb54e4382749279a75691 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 15 Jun 2026 22:51:43 +0800 Subject: [PATCH] Add detailed timing logs to MCP node creation and HTTP client Logs with [MCP-TIMING] prefix at: - create_node_handler entry, setup, http_call start/end, total - http_call entry, auth, response - _authenticate_v3 entry, done, fail --- .../gns3_copilot/gns3_client/custom_gns3fy.py | 16 ++++++++++++++++ gns3server/api/routes/mcp/nodes.py | 14 ++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py b/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py index 0cfe4c5c7..a0c891c8a 100644 --- a/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py +++ b/gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py @@ -49,6 +49,7 @@ 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 @@ -75,6 +76,8 @@ F = TypeVar("F", bound=Callable[..., Any]) config = ConfigDict(validate_assignment=True, extra="ignore") +log = logging.getLogger(__name__) + NODE_TYPES = [ "cloud", "nat", @@ -211,6 +214,9 @@ 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 @@ -249,7 +255,9 @@ 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: """ @@ -291,6 +299,10 @@ 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 ( self.auth_type == "jwt" @@ -299,6 +311,7 @@ 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()) @@ -320,9 +333,12 @@ 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/mcp/nodes.py b/gns3server/api/routes/mcp/nodes.py index 2c1af4936..a2a48898c 100644 --- a/gns3server/api/routes/mcp/nodes.py +++ b/gns3server/api/routes/mcp/nodes.py @@ -203,6 +203,10 @@ 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: return {"error": "project_id is required"} @@ -215,10 +219,12 @@ 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) def _create_one(node_data): + _t1 = time.time() tid = node_data.get("template_id", default_tid) if not tid: return {"template_id": tid, "status": "error", "error": "template_id is required"} @@ -232,17 +238,22 @@ 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"} @@ -256,7 +267,10 @@ def create_node_handler(params: dict[str, Any], gns3_ctx: dict[str, Any]) -> dic if node_name: 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)