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

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
 

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)