NgTech-LTD/gns3-server
2
0
Fork 0
mirror of https://github.com/GNS3/gns3-server.git synced 2026-09-03 00:25:17 +03:00
Code Issues Packages Projects Releases Wiki Activity

Clean up all timing/debug logs

Browse Source 
Remove all [MCP-TIMING] and [CTRL-TIMING] log lines, timing middleware,
and related import time statements across 11 files.
This commit is contained in:
YueGuobin 2026-06-16 00:34:11 +08:00
parent 8ef70d9fac
commit ccb629f48f
No known key found for this signature in database
11 changed files with 1 additions and 79 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
gns3server/agent/gns3_copilot/gns3_client/custom_gns3fy.py
View File

@ -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

3
gns3server/api/routes/controller/dependencies/authentication.py
View File

@ -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_<api_key_id>_<random_secret>
# 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

2
gns3server/api/routes/controller/dependencies/database.py
View File

@ -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()

5
gns3server/api/routes/controller/projects.py
View File

@ -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

9
gns3server/api/routes/mcp/nodes.py
View File

@ -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)

17
gns3server/api/server.py
View File

@ -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

3
gns3server/controller/compute.py
View File

@ -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 (

4
gns3server/controller/node.py
View File

@ -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":

10
gns3server/controller/project.py
View File

@ -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

12
gns3server/db/repositories/templates.py
View File

@ -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]:

2
gns3server/services/templates.py
View File

@ -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: