From acc9e670af91e0834079755657f41a4cbff57bce Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 22:36:41 +0800 Subject: [PATCH 01/32] perf: parallelize UDP port allocation and NIO creation in UDPLink.create MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously the two sides' UDP port reservations and NIO tunnel POSTs were issued sequentially, even though they are independent once the peer addresses are known — each node talks to its own compute/uBridge with no shared lock, so the HTTP round-trips can overlap. - Port allocation: gather _allocate_port for both computes - NIO creation: gather both node.post calls together - Error handling: if either side fails, roll back whichever side succeeded (previously only node2-fails→cleanup-node1) before re-raising the first error Batch loading (open/import project) benefits most because links are created at high concurrency and the per-link wall-clock time is dominated by the sum of its two sequential NIO POSTs. --- gns3server/controller/udp_link.py | 69 ++++++++++++++++++++----------- 1 file changed, 45 insertions(+), 24 deletions(-) diff --git a/gns3server/controller/udp_link.py b/gns3server/controller/udp_link.py index b25e1126b..5094beccc 100644 --- a/gns3server/controller/udp_link.py +++ b/gns3server/controller/udp_link.py @@ -16,6 +16,8 @@ # along with this program. If not, see . +import asyncio + from .controller_error import ControllerError, ControllerNotFoundError from .link import Link, _UNSET from .node_types import BUILTIN_NODE_TYPES @@ -99,25 +101,25 @@ class UDPLink(Link): except ValueError as e: raise ControllerError(f"Cannot get an IP address on same subnet: {e}") - # Reserve a UDP port on both side - # Try pre-allocated ports first (used during batch project loading) - port = self._project.pop_preallocated_udp_port(node1.compute.id) - if port is not None: - self._node1_port = port - else: - response = await node1.compute.post(f"/projects/{self._project.id}/ports/udp") - self._node1_port = response.json["udp_port"] - port = self._project.pop_preallocated_udp_port(node2.compute.id) - if port is not None: - self._node2_port = port - else: - response = await node2.compute.post(f"/projects/{self._project.id}/ports/udp") - self._node2_port = response.json["udp_port"] + # Reserve a UDP port on both sides in parallel. Pre-allocated ports + # (used during batch project loading) are popped from memory; otherwise + # each side falls back to a single HTTP round-trip to its compute. + async def _allocate_port(compute): + port = self._project.pop_preallocated_udp_port(compute.id) + if port is not None: + return port + response = await compute.post(f"/projects/{self._project.id}/ports/udp") + return response.json["udp_port"] + + self._node1_port, self._node2_port = await asyncio.gather( + _allocate_port(node1.compute), _allocate_port(node2.compute) + ) node1_filters, node2_filters = self._get_node_filters(node1, node2) node1_markers, node2_markers = self._get_node_markers(node1, node2) - # Create the tunnel on both side + # Build the tunnel specs for both sides. Index 0 is always node1 so + # that update()/delete() keep addressing self._link_data[0]/[1]. self._link_data.append( { "lport": self._node1_port, @@ -129,8 +131,6 @@ class UDPLink(Link): "suspend": self._suspended, } ) - await node1.post(f"/adapters/{adapter_number1}/ports/{port_number1}/nio", data=self._link_data[0], timeout=120) - self._link_data.append( { "lport": self._node2_port, @@ -142,14 +142,35 @@ class UDPLink(Link): "suspend": self._suspended, } ) - try: - await node2.post( + + # Create the NIO tunnel on both sides in parallel. The two ends are + # independent once the ports and peer addresses are known -- each node + # talks to its own compute/uBridge with no shared lock between them -- + # so the two POSTs overlap. If either fails, roll back whichever side + # succeeded before re-raising the first error. + results = await asyncio.gather( + node1.post( + f"/adapters/{adapter_number1}/ports/{port_number1}/nio", data=self._link_data[0], timeout=120 + ), + node2.post( f"/adapters/{adapter_number2}/ports/{port_number2}/nio", data=self._link_data[1], timeout=120 - ) - except Exception as e: - # We clean the first NIO - await node1.delete(f"/adapters/{adapter_number1}/ports/{port_number1}/nio", timeout=120) - raise e + ), + return_exceptions=True, + ) + errors = [result for result in results if isinstance(result, Exception)] + if errors: + cleanup = [] + if not isinstance(results[0], Exception): + cleanup.append( + node1.delete(f"/adapters/{adapter_number1}/ports/{port_number1}/nio", timeout=120) + ) + if not isinstance(results[1], Exception): + cleanup.append( + node2.delete(f"/adapters/{adapter_number2}/ports/{port_number2}/nio", timeout=120) + ) + if cleanup: + await asyncio.gather(*cleanup, return_exceptions=True) + raise errors[0] self._created = True # New links automatically inherit every active project-level marker # definition so the user doesn't have to reconfigure. From 82fc7f2bd1956bcc0c0ee3e7baf97499de28c621 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 22:45:32 +0800 Subject: [PATCH 02/32] debug: add per-command timing to _connect_nio ubridge calls Temporary diagnostic instrumentation to measure the wall-clock time of each ubridge command during NIO addition (add_nio_udp, bridge start, filters, markers). The logs will reveal whether the 12-NIO/s throughput stems from ubridge command latency itself or from lock contention / HTTP overhead outside _connect_nio. --- gns3server/compute/docker/docker_vm.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index e6f2aee1a..fb7bf66c5 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -27,6 +27,7 @@ import aiohttp import subprocess import os import re +import time from gns3server.utils.asyncio.ssh_server import AsyncioSSHServer from gns3server.utils.asyncio.telnet_server import AsyncioTelnetServer @@ -1215,6 +1216,7 @@ class DockerVM(BaseNode): return int(result["State"]["Pid"]) async def _connect_nio(self, adapter_number, nio): + _t0 = time.perf_counter() bridge_name = f"bridge{adapter_number}" await self._ubridge_send( @@ -1222,6 +1224,7 @@ class DockerVM(BaseNode): bridge_name=bridge_name, lport=nio.lport, rhost=nio.rhost, rport=nio.rport ) ) + _t1 = time.perf_counter() if nio.capturing: await self._ubridge_send( @@ -1230,8 +1233,17 @@ class DockerVM(BaseNode): ) ) await self._ubridge_send(f"bridge start {bridge_name}") + _t2 = time.perf_counter() await self._ubridge_apply_filters(bridge_name, nio.filters) + _t3 = time.perf_counter() await self._ubridge_apply_markers(bridge_name, nio) + _t4 = time.perf_counter() + log.info( + "NIO timing [adapter=%d] add_nio_udp=%.3fms start=%.3fms filters=%.3fms markers=%.3fms total=%.3fms", + adapter_number, + 1000 * (_t1 - _t0), 1000 * (_t2 - _t1), + 1000 * (_t3 - _t2), 1000 * (_t4 - _t3), + 1000 * (_t4 - _t0)) async def adapter_add_nio_binding(self, adapter_number, nio): """ From 506b0b9f4a8b489fb133db1b99527711bc436564 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:00:59 +0800 Subject: [PATCH 03/32] perf: enable TCP keep-alive for local compute HTTP requests When controller and compute share the same process, every HTTP request to localhost was paying a full TCP handshake (force_close=True forced connection teardown after each request). With 2500+ links each sending two NIO POSTs, that's 5000 SYN->SYN-ACK->ACK cycles even for sub-ms in-memory handlers. Switch to keep-alive for loopback compute (127.0.0.1 / ::1 / localhost) while keeping force_close for remote computes that may sit behind NAT/firewalls that drop idle connections. --- gns3server/controller/compute.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/gns3server/controller/compute.py b/gns3server/controller/compute.py index 7ec8691a8..d32a1a84a 100644 --- a/gns3server/controller/compute.py +++ b/gns3server/controller/compute.py @@ -102,7 +102,13 @@ class Compute: def _session(self): if self._http_session is None or self._http_session.closed is True: - connector = aiohttp.TCPConnector(force_close=True, ssl_context=self._ssl_context) + # Reuse TCP keep-alive for local compute (loopback) to avoid paying + # a TCP handshake on every HTTP request; force-close for remote + # computes in case intermediate firewalls/NATs drop idle connections. + _local = self._host in ("127.0.0.1", "::1", "localhost") + connector = aiohttp.TCPConnector( + force_close=not _local, ssl_context=self._ssl_context + ) self._http_session = aiohttp.ClientSession(connector=connector) return self._http_session From 05934fa8e85300125877c4c97c1b38fba1fe02b9 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:06:54 +0800 Subject: [PATCH 04/32] perf: offload per-NIO ubridge commands to thread-pool executor Replace the 3-5 sequential await _ubridge_send calls in _connect_nio with a single run_in_executor batch. The batch holds the node-level asyncio Lock to prevent interleaving with async sends, then uses the hypervisor's new send_batch_sync method which does blocking socket sendall/recv inside the thread pool. Different nodes' batches now run in true OS-thread parallelism rather than serialising through the asyncio event loop between every command. - ubridge_hypervisor.send_batch_sync: blocking batch send using the underlying socket from the asyncio transport, protected by threading.Lock. - _connect_nio: builds command list (add_nio_udp, start_capture, bridge start, reset_packet_filters, add_packet_filter) and dispatches to the default executor. --- gns3server/compute/docker/docker_vm.py | 54 ++++++++------- .../compute/ubridge/ubridge_hypervisor.py | 66 +++++++++++++++++++ tests/compute/docker/test_docker_vm.py | 9 ++- 3 files changed, 103 insertions(+), 26 deletions(-) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index fb7bf66c5..6f2c425ba 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -27,7 +27,6 @@ import aiohttp import subprocess import os import re -import time from gns3server.utils.asyncio.ssh_server import AsyncioSSHServer from gns3server.utils.asyncio.telnet_server import AsyncioTelnetServer @@ -1216,34 +1215,43 @@ class DockerVM(BaseNode): return int(result["State"]["Pid"]) async def _connect_nio(self, adapter_number, nio): - _t0 = time.perf_counter() bridge_name = f"bridge{adapter_number}" - await self._ubridge_send( - "bridge add_nio_udp {bridge_name} {lport} {rhost} {rport}".format( - bridge_name=bridge_name, lport=nio.lport, rhost=nio.rhost, rport=nio.rport - ) - ) - _t1 = time.perf_counter() + # Build the command batch for this NIO. We send everything in one + # executor call so that a single async-lock acquisition covers the + # whole batch, and different nodes' batches can overlap in the + # thread pool via blocking socket I/O. + commands = [ + f"bridge add_nio_udp {bridge_name} {nio.lport} {nio.rhost} {nio.rport}", + ] if nio.capturing: - await self._ubridge_send( - 'bridge start_capture {bridge_name} "{pcap_file}"'.format( - bridge_name=bridge_name, pcap_file=nio.pcap_output_file - ) + commands.append(f'bridge start_capture {bridge_name} "{nio.pcap_output_file}"') + commands.append(f"bridge start {bridge_name}") + commands.append(f"bridge reset_packet_filters {bridge_name}") + for packet_filter in self._build_filter_list(nio.filters): + commands.append(f"bridge add_packet_filter {bridge_name} {packet_filter}") + + # Hold the per-node ubridge lock across the entire executor batch so + # that no async _ubridge_send for this node can interleave with the + # sync socket writes. The lock is created lazily (mirrors the + # @locking decorator on _ubridge_send). + lock_name = "___ubridge_send_lock" + if not hasattr(self, lock_name): + setattr(self, lock_name, asyncio.Lock()) + async with getattr(self, lock_name): + loop = asyncio.get_running_loop() + await loop.run_in_executor( + None, # default thread-pool executor + self._ubridge_hypervisor.send_batch_sync, + commands, ) - await self._ubridge_send(f"bridge start {bridge_name}") - _t2 = time.perf_counter() - await self._ubridge_apply_filters(bridge_name, nio.filters) - _t3 = time.perf_counter() + + # Traffic-insight markers are rare — keep them on the async path so + # they benefit from the existing marker-management logic. The + # per-node lock is already released at this point, but markers + # serialise themselves via _ubridge_send's own @locking. await self._ubridge_apply_markers(bridge_name, nio) - _t4 = time.perf_counter() - log.info( - "NIO timing [adapter=%d] add_nio_udp=%.3fms start=%.3fms filters=%.3fms markers=%.3fms total=%.3fms", - adapter_number, - 1000 * (_t1 - _t0), 1000 * (_t2 - _t1), - 1000 * (_t3 - _t2), 1000 * (_t4 - _t3), - 1000 * (_t4 - _t0)) async def adapter_add_nio_binding(self, adapter_number, nio): """ diff --git a/gns3server/compute/ubridge/ubridge_hypervisor.py b/gns3server/compute/ubridge/ubridge_hypervisor.py index 83f765d16..740c22378 100644 --- a/gns3server/compute/ubridge/ubridge_hypervisor.py +++ b/gns3server/compute/ubridge/ubridge_hypervisor.py @@ -18,6 +18,7 @@ import re import time import logging import asyncio +import threading from gns3server.utils.asyncio import locking from .ubridge_error import UbridgeError @@ -57,6 +58,8 @@ class UBridgeHypervisor: self._timeout = timeout self._reader = None self._writer = None + self._recv_buf = b"" # leftover bytes from last sync recv + self._send_lock = threading.Lock() async def connect(self, timeout=10): """ @@ -266,3 +269,66 @@ class UBridgeHypervisor: log.debug(f"returned result {data}") return data + + def send_batch_sync(self, commands): + """ + Send multiple commands to uBridge using blocking socket I/O. Designed + to run inside ``loop.run_in_executor`` so that a single per-node batch + doesn't bounce through the event loop between every command, and + batches for *different* nodes run in parallel across the thread pool. + + :param commands: iterable of command strings + :raises UbridgeError: if any command fails + """ + if self._writer is None: + raise UbridgeError("Not connected") + transport = self._writer.transport + if transport is None or transport.is_closing(): + raise UbridgeError("Transport closed") + sock = transport.get_extra_info("socket") + if sock is None: + raise UbridgeError("No underlying socket for sync send_batch") + + # Serialise access to this hypervisor's socket — only one batch (sync + # or async) talks to uBridge at a time. The node-level async lock + # (:func:`_ubridge_send`) is held for the entire executor call, so no + # async ``send()`` can interleave. + with self._send_lock: + sock.setblocking(True) + try: + for command in commands: + cmd = (command.strip() + "\n").encode() + sock.sendall(cmd) + + # Read until the terminating line (100-… or 2xx-…) + buf = self._recv_buf + while True: + try: + chunk = sock.recv(4096) + except BlockingIOError: + continue + if not chunk: + raise UbridgeError( + f"uBridge closed connection during '{command}'" + ) + buf += chunk + decoded = buf.decode("utf-8", errors="replace") + # Last complete line determines termination + tail = decoded.rsplit("\r\n", 1)[-1] + if tail and tail[0] in "12" and tail[1:3].isdigit() and len(tail) >= 4 and tail[3] == "-": + break + + # Check for error codes (2xx-…) + last_line = decoded.strip().split("\r\n")[-1] + if self.error_re.match(last_line): + raise UbridgeError(last_line[4:]) + + # Keep any leftover bytes (after the trailing \r\n) for the + # next read in the batch + trailer_start = decoded.rfind("\r\n") + if trailer_start >= 0: + self._recv_buf = buf[trailer_start + 2:] + else: + self._recv_buf = b"" + finally: + sock.setblocking(False) diff --git a/tests/compute/docker/test_docker_vm.py b/tests/compute/docker/test_docker_vm.py index 9d8bee2b8..ae40d91d9 100644 --- a/tests/compute/docker/test_docker_vm.py +++ b/tests/compute/docker/test_docker_vm.py @@ -1440,9 +1440,12 @@ async def test_add_ubridge_connection(vm): call.send('bridge create bridge0'), call.send("bridge add_nio_tap bridge0 tap-gns3-e0"), call.send('docker move_to_ns tap-gns3-e0 42 eth0'), - call.send('bridge add_nio_udp bridge0 4242 127.0.0.1 4343'), - call.send('bridge start_capture bridge0 "/tmp/capture.pcap"'), - call.send('bridge start bridge0') + call.send_batch_sync([ + 'bridge add_nio_udp bridge0 4242 127.0.0.1 4343', + 'bridge start_capture bridge0 "/tmp/capture.pcap"', + 'bridge start bridge0', + 'bridge reset_packet_filters bridge0', + ]), ] assert 'bridge0' in vm._bridges # We need to check any_order otherwise mock is confused by asyncio From b155980402ce7a19ea1f845953d93eb2e58efe2c Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:11:23 +0800 Subject: [PATCH 05/32] perf: dedicated 500-worker thread pool for ubridge batch I/O MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace the default asyncio executor (capped at ~32 threads) with a dedicated ThreadPoolExecutor sized for large-topology parallelism. When 500 nodes each call _connect_nio, up to 500 OS threads can now send blocking ubridge commands in parallel — no longer serialised by either the event loop or a small thread pool. - ubridge_hypervisor: module-level _ubridge_sync_pool (max_workers=500) - docker_vm._connect_nio: dispatches to the dedicated pool instead of the default executor --- gns3server/compute/docker/docker_vm.py | 3 ++- gns3server/compute/ubridge/ubridge_hypervisor.py | 11 +++++++++++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index 6f2c425ba..ee387e76f 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -38,6 +38,7 @@ from gns3server.utils.hostname import is_rfc1123_hostname_valid from gns3server.utils import macaddress_to_int, int_to_macaddress from gns3server.compute.ubridge.ubridge_error import UbridgeError, UbridgeNamespaceError +from gns3server.compute.ubridge.ubridge_hypervisor import _ubridge_sync_pool from ..base_node import BaseNode from ..adapters.ethernet_adapter import EthernetAdapter @@ -1242,7 +1243,7 @@ class DockerVM(BaseNode): async with getattr(self, lock_name): loop = asyncio.get_running_loop() await loop.run_in_executor( - None, # default thread-pool executor + _ubridge_sync_pool, # dedicated 500-worker thread pool self._ubridge_hypervisor.send_batch_sync, commands, ) diff --git a/gns3server/compute/ubridge/ubridge_hypervisor.py b/gns3server/compute/ubridge/ubridge_hypervisor.py index 740c22378..68a84e477 100644 --- a/gns3server/compute/ubridge/ubridge_hypervisor.py +++ b/gns3server/compute/ubridge/ubridge_hypervisor.py @@ -19,12 +19,23 @@ import time import logging import asyncio import threading +import concurrent.futures from gns3server.utils.asyncio import locking from .ubridge_error import UbridgeError log = logging.getLogger(__name__) +# Dedicated thread pool for blocking ubridge socket I/O. Every node gets +# its own ubridge process + socket, so N nodes can send commands in true +# OS-thread parallelism. The default asyncio executor caps at ~32 threads; +# sizing for the large-topology case (2500+ links → thousands of NIO add +# calls across hundreds of nodes). +_ubridge_sync_pool = concurrent.futures.ThreadPoolExecutor( + max_workers=500, + thread_name_prefix="ubridge-sync", +) + class UBridgeHypervisor: From 96d4d82716a29ca94ece807ef944c3c061cd2308 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:20:40 +0800 Subject: [PATCH 06/32] perf: cache compute.host_ip + add UDPLink.create timing log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit host_ip resolved socket.gethostbyname on every access with no cache. get_ip_on_same_subnet touches host_ip 2-4 times per link, so opening a 2500-link project issued thousands of blocking DNS calls inline on the event loop — freezing all concurrent link coroutines each time. This is the most likely cause of the 12-link/s throughput (1000x below what Pool(concurrency=100) should deliver) and the burst+pause pattern. - compute.host_ip: cache the resolution in _host_ip_cache, invalidate on host setter change - UDPLink.create: timing log splitting get_ip / ports / nio so the next project-open confirms where time actually goes --- gns3server/controller/compute.py | 15 +++++++++++---- gns3server/controller/udp_link.py | 13 +++++++++++++ 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/gns3server/controller/compute.py b/gns3server/controller/compute.py index d32a1a84a..16d6037df 100644 --- a/gns3server/controller/compute.py +++ b/gns3server/controller/compute.py @@ -98,6 +98,10 @@ class Compute: self.name = name # Cache of interfaces on remote host self._interfaces_cache = None + # Cached resolution of self._host — socket.gethostbyname is a blocking + # call; resolving it on every host_ip access (several times per link + # via get_ip_on_same_subnet) freezes the event loop for all coroutines. + self._host_ip_cache = None self._connection_failure = 0 def _session(self): @@ -224,14 +228,17 @@ class Compute: """ Return the IP associated to the host """ - try: - return socket.gethostbyname(self._host) - except socket.gaierror: - return "0.0.0.0" + if self._host_ip_cache is None: + try: + self._host_ip_cache = socket.gethostbyname(self._host) + except socket.gaierror: + self._host_ip_cache = "0.0.0.0" + return self._host_ip_cache @host.setter def host(self, host): self._host = host + self._host_ip_cache = None # invalidate; re-resolve on next access if self._console_host is None: self._console_host = host diff --git a/gns3server/controller/udp_link.py b/gns3server/controller/udp_link.py index 5094beccc..680fcba51 100644 --- a/gns3server/controller/udp_link.py +++ b/gns3server/controller/udp_link.py @@ -17,6 +17,8 @@ import asyncio +import time +import logging from .controller_error import ControllerError, ControllerNotFoundError from .link import Link, _UNSET @@ -32,6 +34,9 @@ _MARKER_CAPABLE_TYPES = frozenset({ }) +log = logging.getLogger(__name__) + + class UDPLink(Link): def __init__(self, project, link_id=None): super().__init__(project, link_id=link_id) @@ -96,10 +101,12 @@ class UDPLink(Link): port_number2 = self._nodes[1]["port_number"] # Get an IP allowing communication between both host + _t0 = time.perf_counter() try: (node1_host, node2_host) = await node1.compute.get_ip_on_same_subnet(node2.compute) except ValueError as e: raise ControllerError(f"Cannot get an IP address on same subnet: {e}") + _t1 = time.perf_counter() # Reserve a UDP port on both sides in parallel. Pre-allocated ports # (used during batch project loading) are popped from memory; otherwise @@ -114,6 +121,7 @@ class UDPLink(Link): self._node1_port, self._node2_port = await asyncio.gather( _allocate_port(node1.compute), _allocate_port(node2.compute) ) + _t2 = time.perf_counter() node1_filters, node2_filters = self._get_node_filters(node1, node2) node1_markers, node2_markers = self._get_node_markers(node1, node2) @@ -171,6 +179,11 @@ class UDPLink(Link): if cleanup: await asyncio.gather(*cleanup, return_exceptions=True) raise errors[0] + _t3 = time.perf_counter() + log.info( + "UDPLink.create timing get_ip=%.3fms ports=%.3fms nio=%.3fms total=%.3fms", + 1000 * (_t1 - _t0), 1000 * (_t2 - _t1), 1000 * (_t3 - _t2), 1000 * (_t3 - _t0) + ) self._created = True # New links automatically inherit every active project-level marker # definition so the user doesn't have to reconfigure. From 38c49a655cb0b3d1b31a66ee594d25df25837484 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:42:50 +0800 Subject: [PATCH 07/32] perf: batch NIO dispatch on project open (one HTTP per compute) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Project open used to create each link by issuing two NIO POSTs from the controller to the compute — ~5000 HTTP round-trips for a 2500-link topology, all funnelling through the single shared controller/compute event loop and capping throughput near 12 links/s. Replace it with a bulk path: - UDPLink split into _prepare() (local: ports, peer addrs, link_data) and _commit_nios() (dispatch). create() = prepare + commit (interactive). - Link.add_node gains batch=True: attach both nodes without triggering per-link NIO HTTP. - compute: new POST /projects/{id}/nios/batch endpoint with a unified _add_nio_binding dispatch across node types (docker/qemu/iou/vpcs/ builtin differ in signature). - project.open: prepare all links locally, group NIO entries by compute, send each compute a single /nios/batch, then finalise (wire node/port refs, mark created, notify, apply marker defs) in parallel. Cuts controller->compute HTTP from O(links) to O(computes). Test added for the batch endpoint. --- gns3server/api/routes/compute/projects.py | 55 +++++++ gns3server/controller/link.py | 7 +- gns3server/controller/project.py | 138 +++++++++++++++++- gns3server/controller/udp_link.py | 56 ++++--- gns3server/schemas/__init__.py | 2 +- gns3server/schemas/compute/nios.py | 23 ++- tests/api/routes/compute/test_docker_nodes.py | 28 ++++ 7 files changed, 280 insertions(+), 29 deletions(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index 71245dfe7..5a4cb63fd 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -34,6 +34,7 @@ from uuid import UUID from gns3server.compute.project_manager import ProjectManager from gns3server.compute.project import Project +from gns3server.compute.base_manager import BaseManager from gns3server.utils.path import is_safe_path from gns3server import schemas @@ -131,6 +132,60 @@ async def delete_compute_project(project: Project = Depends(dep_project)) -> Non ProjectManager.instance().remove_project(project.id) +async def _add_nio_binding(node, adapter_number, port_number, nio): + """ + Unified NIO-binding dispatch across node types. Each node type exposes a + different method signature, so centralise the fan-out here for the batch + endpoint. Dispatch keys off the manager class name (only dynamips/iou/qemu + carry a ``_NODE_TYPE`` attribute, so it can't be used universally). + """ + + manager_name = type(node.manager).__name__ + # Adapter-based nodes: docker / qemu / vmware / virtualbox take + # (adapter_number, nio); iou additionally takes port_number. + if manager_name in ("Docker", "Qemu", "VMware", "VirtualBox"): + await node.adapter_add_nio_binding(adapter_number, nio) + elif manager_name == "IOU": + await node.adapter_add_nio_binding(adapter_number, port_number, nio) + elif manager_name == "VPCS": + await node.port_add_nio_binding(port_number, nio) + elif manager_name == "Builtin": + # ethernet_switch / ethernet_hub / cloud / nat: add_nio(nio, port_number) + await node.add_nio(nio, port_number) + else: + raise HTTPException( + status_code=status.HTTP_400_BAD_REQUEST, + detail=f"Batch NIO creation not supported for node type '{manager_name}'", + ) + + +@router.post( + "/projects/{project_id}/nios/batch", + status_code=status.HTTP_201_CREATED, +) +async def create_batch_nios( + project_id: UUID, + batch: schemas.BatchNIOCreate, + project: Project = Depends(dep_project), +) -> dict: + """ + Create many NIO bindings across nodes in a single request. + + Used by the controller during project open to avoid one HTTP round-trip per + NIO. Each entry resolves its node via the project, builds the NIO through + the node's manager, and binds it. Nodes that are not started perform the + binding in memory; started nodes additionally wire uBridge. + """ + + added = 0 + for entry in batch.nios: + node = project.get_node(entry.node_id) + nio = node.manager.create_nio(jsonable_encoder(entry.nio, exclude_unset=True)) + await _add_nio_binding(node, entry.adapter_number, entry.port_number, nio) + added += 1 + return {"added": added} + + @router.get("/projects/{project_id}/files", response_model=List[schemas.ProjectFile]) async def get_compute_project_files(project: Project = Depends(dep_project)) -> List[schemas.ProjectFile]: """ diff --git a/gns3server/controller/link.py b/gns3server/controller/link.py index e716bfd03..0cc00a140 100644 --- a/gns3server/controller/link.py +++ b/gns3server/controller/link.py @@ -257,11 +257,14 @@ class Link: """ return self._created - async def add_node(self, node, adapter_number, port_number, label=None, dump=True): + async def add_node(self, node, adapter_number, port_number, label=None, dump=True, batch=False): """ Add a node to the link :param dump: Dump project on disk + :param batch: When True, do not create the link on the computes once + both nodes are attached — the caller drives creation via the + project-open bulk path. Used to avoid one HTTP round-trip per link. """ port = node.get_port(adapter_number, port_number) @@ -305,7 +308,7 @@ class Link: {"node": node, "adapter_number": adapter_number, "port_number": port_number, "port": port, "label": label} ) - if len(self._nodes) == 2: + if len(self._nodes) == 2 and not batch: await self.create() for n in self._nodes: n["node"].add_link(self) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index a6bcc159c..a23c1095f 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -827,6 +827,81 @@ class Project: # a link should have 2 attached nodes, this can happen with corrupted projects await self.delete_link(link.id, force_delete=True) + async def _prepare_link_from_topology(self, link_data): + """ + Build a link locally from topology data WITHOUT dispatching NIOs to the + computes. Returns ``(link, entries)`` where ``entries`` is the list of + ``(node, adapter_number, port_number, nio_data)`` tuples produced by + ``UDPLink._prepare()``, or ``None`` if the link is invalid/incomplete. + + Used by the project-open bulk path so all NIOs can be sent in a single + batch HTTP call per compute instead of one round-trip per link. + """ + + link = await self.add_link(link_id=link_data["link_id"]) + if "filters" in link_data: + try: + await link.update_filters(link_data["filters"]) + except ControllerError as e: + log.warning("Dropping invalid filters on link %s: %s", link_data.get("link_id"), e) + for name, marker in (link_data.get("markers") or {}).items(): + bpf = marker.get("bpf") + if not bpf: + log.warning("Dropping marker %s on link %s: missing bpf", name, link_data.get("link_id")) + continue + result = validate_bpf_syntax(bpf) + if not result.get("valid"): + log.warning( + "Dropping marker %s on link %s: invalid BPF (%s)", + name, link_data.get("link_id"), result.get("error") + ) + continue + link._markers[name] = { + "bpf": bpf, + "tag": marker.get("tag"), + "enabled": marker.get("enabled", True), + "color": marker.get("color"), + "highlight_duration": marker.get("highlight_duration"), + "capture_node_id": marker.get("capture_node_id"), + "direction": marker.get("direction"), + } + if "link_style" in link_data: + await link.update_link_style(link_data["link_style"]) + if "show_filters_icon" in link_data: + await link.update_show_filters_icon(link_data["show_filters_icon"]) + for node_link in link_data.get("nodes", []): + node = self.get_node(node_link["node_id"]) + port = node.get_port(node_link["adapter_number"], node_link["port_number"]) + if port is None: + log.warning( + "Port {}/{} for {} not found".format( + node_link["adapter_number"], node_link["port_number"], node.name + ) + ) + continue + if port.link is not None: + log.warning( + "Port {}/{} is already connected to link ID {}".format( + node_link["adapter_number"], node_link["port_number"], port.link.id + ) + ) + continue + # batch=True: attach the node without triggering per-link NIO HTTP + await link.add_node( + node, + node_link["adapter_number"], + node_link["port_number"], + label=node_link.get("label"), + dump=False, + batch=True, + ) + if len(link.nodes) != 2: + # a link should have 2 attached nodes, this can happen with corrupted projects + await self.delete_link(link.id, force_delete=True) + return None + entries = await link._prepare() + return (link, entries) + @open_required async def add_link(self, link_id=None, dump=True): """ @@ -1648,13 +1723,62 @@ class Project: count = ports_per_compute.get(compute.id, 0) if count > 0: await self.preallocate_udp_ports_for_compute(compute, count) - # Create links in parallel for improved performance - pool = Pool(concurrency=100) - for link_data in topology.get("links", []): - if "link_id" not in link_data.keys(): - continue - pool.append(self._create_link_from_topology_data, link_data) - await pool.join() + # Create links via the bulk path: build every link locally (no NIO + # HTTP), then dispatch all NIOs to each compute in a single batch + # request. This replaces one HTTP round-trip per link (~5000 for a + # 2500-link topology) with one round-trip per compute. + link_data_list = [d for d in topology.get("links", []) if "link_id" in d.keys()] + sem = asyncio.Semaphore(100) + + async def _prepare_one(data): + async with sem: + try: + return await self._prepare_link_from_topology(data) + except Exception as e: + log.warning("Could not load link %s: %s", data.get("link_id"), e) + return None + + prepared = await asyncio.gather(*[_prepare_one(d) for d in link_data_list]) + valid = [p for p in prepared if p is not None] + + # Group the prepared NIO entries by destination compute and send + # each compute a single /nios/batch request. + per_compute = {} # compute -> list of {node_id, adapter_number, port_number, nio} + for link, entries in valid: + for node, adapter_number, port_number, nio_data in entries: + per_compute.setdefault(node.compute, []).append( + { + "node_id": node.id, + "adapter_number": adapter_number, + "port_number": port_number, + "nio": nio_data, + } + ) + + async def _dispatch_batch(compute, nio_entries): + await compute.post( + f"/projects/{self._id}/nios/batch", + data={"nios": nio_entries}, + timeout=300, + ) + + if per_compute: + await asyncio.gather( + *[_dispatch_batch(c, n) for c, n in per_compute.items()] + ) + + # Finalise every link: wire node/port back-references, mark created, + # notify clients, and apply project-level marker definitions. + for link, _entries in valid: + for n in link._nodes: + n["node"].add_link(link) + n["port"].link = link + link._created = True + self.emit_notification("link.created", link.asdict()) + if valid: + await asyncio.gather( + *[self.apply_defs_to_new_link(link) for link, _ in valid] + ) # Release any pre-allocated UDP ports that were not consumed by links for compute_id, ports in self._preallocated_udp_ports.items(): if ports: diff --git a/gns3server/controller/udp_link.py b/gns3server/controller/udp_link.py index 680fcba51..7e9517989 100644 --- a/gns3server/controller/udp_link.py +++ b/gns3server/controller/udp_link.py @@ -17,7 +17,6 @@ import asyncio -import time import logging from .controller_error import ControllerError, ControllerNotFoundError @@ -88,9 +87,15 @@ class UDPLink(Link): """ return self._markers_for_node(node1), self._markers_for_node(node2) - async def create(self): + async def _prepare(self): """ - Create the link on the nodes + Local-only link setup: resolve peer addresses, reserve UDP ports and + build the two NIO tunnel specs (``self._link_data``). No NIO is sent to + the computes — the caller decides how to dispatch them (one-by-one via + :meth:`create`, or batched via the project-open bulk path). + + :returns: list of two ``(node, adapter_number, port_number, nio_data)`` + tuples, ready to be POSTed to each node's compute. """ node1 = self._nodes[0]["node"] @@ -101,12 +106,10 @@ class UDPLink(Link): port_number2 = self._nodes[1]["port_number"] # Get an IP allowing communication between both host - _t0 = time.perf_counter() try: (node1_host, node2_host) = await node1.compute.get_ip_on_same_subnet(node2.compute) except ValueError as e: raise ControllerError(f"Cannot get an IP address on same subnet: {e}") - _t1 = time.perf_counter() # Reserve a UDP port on both sides in parallel. Pre-allocated ports # (used during batch project loading) are popped from memory; otherwise @@ -121,7 +124,6 @@ class UDPLink(Link): self._node1_port, self._node2_port = await asyncio.gather( _allocate_port(node1.compute), _allocate_port(node2.compute) ) - _t2 = time.perf_counter() node1_filters, node2_filters = self._get_node_filters(node1, node2) node1_markers, node2_markers = self._get_node_markers(node1, node2) @@ -151,17 +153,32 @@ class UDPLink(Link): } ) - # Create the NIO tunnel on both sides in parallel. The two ends are - # independent once the ports and peer addresses are known -- each node - # talks to its own compute/uBridge with no shared lock between them -- - # so the two POSTs overlap. If either fails, roll back whichever side - # succeeded before re-raising the first error. + return [ + (node1, adapter_number1, port_number1, self._link_data[0]), + (node2, adapter_number2, port_number2, self._link_data[1]), + ] + + async def _commit_nios(self, entries): + """ + Send the two NIO tunnel POSTs in parallel and roll back on failure. + + :param entries: the two ``(node, adapter_number, port_number, nio_data)`` + tuples returned by :meth:`_prepare`. + """ + + (node1, adapter_number1, port_number1, nio_data1), \ + (node2, adapter_number2, port_number2, nio_data2) = entries + + # The two ends are independent once the ports and peer addresses are + # known — each node talks to its own compute/uBridge with no shared + # lock between them — so the two POSTs overlap. If either fails, roll + # back whichever side succeeded before re-raising the first error. results = await asyncio.gather( node1.post( - f"/adapters/{adapter_number1}/ports/{port_number1}/nio", data=self._link_data[0], timeout=120 + f"/adapters/{adapter_number1}/ports/{port_number1}/nio", data=nio_data1, timeout=120 ), node2.post( - f"/adapters/{adapter_number2}/ports/{port_number2}/nio", data=self._link_data[1], timeout=120 + f"/adapters/{adapter_number2}/ports/{port_number2}/nio", data=nio_data2, timeout=120 ), return_exceptions=True, ) @@ -179,12 +196,15 @@ class UDPLink(Link): if cleanup: await asyncio.gather(*cleanup, return_exceptions=True) raise errors[0] - _t3 = time.perf_counter() - log.info( - "UDPLink.create timing get_ip=%.3fms ports=%.3fms nio=%.3fms total=%.3fms", - 1000 * (_t1 - _t0), 1000 * (_t2 - _t1), 1000 * (_t3 - _t2), 1000 * (_t3 - _t0) - ) self._created = True + + async def create(self): + """ + Create the link on the nodes (interactive path: prepare + commit). + """ + + entries = await self._prepare() + await self._commit_nios(entries) # New links automatically inherit every active project-level marker # definition so the user doesn't have to reconfigure. await self._project.apply_defs_to_new_link(self) diff --git a/gns3server/schemas/__init__.py b/gns3server/schemas/__init__.py index af026c241..7d4ba6c22 100644 --- a/gns3server/schemas/__init__.py +++ b/gns3server/schemas/__init__.py @@ -91,7 +91,7 @@ from .controller.templates.dynamips_templates import ( ) # Compute schemas -from .compute.nios import UDPNIO, TAPNIO, EthernetNIO, MarkerToggle, MarkerRebuild +from .compute.nios import UDPNIO, TAPNIO, EthernetNIO, MarkerToggle, MarkerRebuild, BatchNIOEntry, BatchNIOCreate from .compute.atm_switch_nodes import ATMSwitchCreate, ATMSwitchUpdate, ATMSwitch from .compute.cloud_nodes import CloudCreate, CloudUpdate, Cloud from .compute.docker_nodes import DockerCreate, DockerUpdate, Docker diff --git a/gns3server/schemas/compute/nios.py b/gns3server/schemas/compute/nios.py index 5830847c5..a1d8641b3 100644 --- a/gns3server/schemas/compute/nios.py +++ b/gns3server/schemas/compute/nios.py @@ -16,7 +16,7 @@ from pydantic import BaseModel, Field -from typing import Optional +from typing import Optional, List from enum import Enum @@ -91,3 +91,24 @@ class MarkerRebuild(BaseModel): direction: Optional[str] = None enabled: bool = True link_id: str = "" + + +class BatchNIOEntry(BaseModel): + """ + A single NIO binding to create as part of a project-wide batch. + """ + + node_id: str = Field(..., description="Node the NIO is attached to") + adapter_number: int = Field(0, ge=0, description="Adapter number") + port_number: int = Field(0, ge=0, description="Port number") + nio: UDPNIO = Field(..., description="NIO settings") + + +class BatchNIOCreate(BaseModel): + """ + Body for the project-wide batch NIO endpoint: create many NIO bindings in a + single request (used during project open) to avoid one HTTP round-trip per + NIO between controller and compute. + """ + + nios: List[BatchNIOEntry] = Field(..., description="NIO bindings to create") diff --git a/tests/api/routes/compute/test_docker_nodes.py b/tests/api/routes/compute/test_docker_nodes.py index ebbba442f..13e4609b7 100644 --- a/tests/api/routes/compute/test_docker_nodes.py +++ b/tests/api/routes/compute/test_docker_nodes.py @@ -211,6 +211,34 @@ class TestDockerNodesRoutes: assert response.status_code == status.HTTP_201_CREATED assert response.json()["type"] == "nio_udp" + async def test_docker_nio_batch_create(self, app: FastAPI, compute_client: AsyncClient, vm: dict) -> None: + """ + Exercise the project-wide batch NIO endpoint: bind two NIOs on the same + docker node in a single request (the path used during project open). + """ + + params = { + "nios": [ + { + "node_id": vm["node_id"], + "adapter_number": 0, + "port_number": 0, + "nio": {"type": "nio_udp", "lport": 4242, "rport": 4343, "rhost": "127.0.0.1"}, + }, + { + "node_id": vm["node_id"], + "adapter_number": 1, + "port_number": 0, + "nio": {"type": "nio_udp", "lport": 4243, "rport": 4344, "rhost": "127.0.0.1"}, + }, + ] + } + + url = app.url_path_for("compute:create_batch_nios", project_id=vm["project_id"]) + response = await compute_client.post(url, json=params) + assert response.status_code == status.HTTP_201_CREATED + assert response.json()["added"] == 2 + async def test_docker_update_nio(self, app: FastAPI, compute_client: AsyncClient, vm: dict) -> None: From c9a93c0aeb00c91b08a4b60ff0fe363b710f649f Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Mon, 10 Aug 2026 23:54:21 +0800 Subject: [PATCH 08/32] perf: skip per-link topology dump during project-open prepare Stage timing showed prepare taking 96s for 1275 links (vs 0.31s for the batch dispatch itself). Root cause: _prepare_link_from_topology called add_link (dump=True default) and update_link_style/update_show_filters_icon (each unconditionally dump the full topology). 1275 links x serialize- and-write-the-whole-topology = the entire 96s. - add_link(..., dump=False): the project is dumped once at the end of open - set link._link_style / _show_filters_icon directly instead of the update_* helpers, which also avoids spurious 'link.updated' notifications before the link is finalised The final self.dump() at the end of project.open already persists everything. --- .gitignore | 1 + gns3server/controller/project.py | 20 +++++++++++++++++--- 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/.gitignore b/.gitignore index 28a535038..5d4619d10 100644 --- a/.gitignore +++ b/.gitignore @@ -85,3 +85,4 @@ venv # Tiktoken cache files gns3server/agent/gns3_copilot/cache/tiktoken/ +gns3.log diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index a23c1095f..3b452eea5 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -838,7 +838,7 @@ class Project: batch HTTP call per compute instead of one round-trip per link. """ - link = await self.add_link(link_id=link_data["link_id"]) + link = await self.add_link(link_id=link_data["link_id"], dump=False) if "filters" in link_data: try: await link.update_filters(link_data["filters"]) @@ -865,10 +865,14 @@ class Project: "capture_node_id": marker.get("capture_node_id"), "direction": marker.get("direction"), } + # Set style/icon directly: the update_* helpers unconditionally dump + # the whole topology and emit "link.updated", neither of which is + # appropriate mid-prepare (the link is finalised, notified and the + # project dumped once at the end of open). if "link_style" in link_data: - await link.update_link_style(link_data["link_style"]) + link._link_style = link_data["link_style"] if "show_filters_icon" in link_data: - await link.update_show_filters_icon(link_data["show_filters_icon"]) + link._show_filters_icon = link_data["show_filters_icon"] for node_link in link_data.get("nodes", []): node = self.get_node(node_link["node_id"]) port = node.get_port(node_link["adapter_number"], node_link["port_number"]) @@ -1706,11 +1710,14 @@ class Project: # Create nodes in parallel with limited concurrency # to avoid overwhelming the system with too many simultaneous operations + _stage_t0 = time.time() pool = Pool(concurrency=100) for compute, name, node_id, node_data in nodes_to_create: pool.append(self.add_node, compute, name, node_id, dump=False, **node_data) await pool.join() + log.info("Project open stage timing: nodes=%d created in %.2fs", len(nodes_to_create), time.time() - _stage_t0) # Pre-allocate UDP ports for all links in batch to reduce HTTP round-trips + _stage_t1 = time.time() ports_per_compute = {} for link_data in topology.get("links", []): if "link_id" not in link_data.keys(): @@ -1723,6 +1730,7 @@ class Project: count = ports_per_compute.get(compute.id, 0) if count > 0: await self.preallocate_udp_ports_for_compute(compute, count) + log.info("Project open stage timing: preallocate ports in %.2fs", time.time() - _stage_t1) # Create links via the bulk path: build every link locally (no NIO # HTTP), then dispatch all NIOs to each compute in a single batch # request. This replaces one HTTP round-trip per link (~5000 for a @@ -1740,6 +1748,7 @@ class Project: prepared = await asyncio.gather(*[_prepare_one(d) for d in link_data_list]) valid = [p for p in prepared if p is not None] + log.info("Project open stage timing: prepare %d links in %.2fs", len(link_data_list), time.time() - _stage_t1) # Group the prepared NIO entries by destination compute and send # each compute a single /nios/batch request. @@ -1763,9 +1772,14 @@ class Project: ) if per_compute: + _stage_t2 = time.time() await asyncio.gather( *[_dispatch_batch(c, n) for c, n in per_compute.items()] ) + log.info( + "Project open stage timing: batch dispatch %d NIOs across %d compute(s) in %.2fs", + sum(len(n) for n in per_compute.values()), len(per_compute), time.time() - _stage_t2 + ) # Finalise every link: wire node/port back-references, mark created, # notify clients, and apply project-level marker definitions. From e2fd9229226cade268c7385133e88e0d0e79b8cc Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:14:58 +0800 Subject: [PATCH 09/32] cleanup: remove project-open stage timing logs, lower NIO-added log to debug MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Drop the diagnostic stage-timing logs added during link-create perf work (nodes / preallocate / prepare / dispatch) now that bottlenecks are resolved and verified. - Lower the per-NIO 'added to adapter' log in docker_vm from INFO to DEBUG — at 5000+ NIOs per project open it floods the log at INFO. --- gns3server/compute/docker/docker_vm.py | 2 +- gns3server/controller/project.py | 10 ---------- 2 files changed, 1 insertion(+), 11 deletions(-) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index ee387e76f..8358b4ed7 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -1275,7 +1275,7 @@ class DockerVM(BaseNode): await self._connect_nio(adapter_number, nio) adapter.add_nio(0, nio) - log.info( + log.debug( "Docker container '{name}' [{id}]: {nio} added to adapter {adapter_number}".format( name=self.name, id=self._id, nio=nio, adapter_number=adapter_number ) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 3b452eea5..587d734f9 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1710,14 +1710,11 @@ class Project: # Create nodes in parallel with limited concurrency # to avoid overwhelming the system with too many simultaneous operations - _stage_t0 = time.time() pool = Pool(concurrency=100) for compute, name, node_id, node_data in nodes_to_create: pool.append(self.add_node, compute, name, node_id, dump=False, **node_data) await pool.join() - log.info("Project open stage timing: nodes=%d created in %.2fs", len(nodes_to_create), time.time() - _stage_t0) # Pre-allocate UDP ports for all links in batch to reduce HTTP round-trips - _stage_t1 = time.time() ports_per_compute = {} for link_data in topology.get("links", []): if "link_id" not in link_data.keys(): @@ -1730,7 +1727,6 @@ class Project: count = ports_per_compute.get(compute.id, 0) if count > 0: await self.preallocate_udp_ports_for_compute(compute, count) - log.info("Project open stage timing: preallocate ports in %.2fs", time.time() - _stage_t1) # Create links via the bulk path: build every link locally (no NIO # HTTP), then dispatch all NIOs to each compute in a single batch # request. This replaces one HTTP round-trip per link (~5000 for a @@ -1748,7 +1744,6 @@ class Project: prepared = await asyncio.gather(*[_prepare_one(d) for d in link_data_list]) valid = [p for p in prepared if p is not None] - log.info("Project open stage timing: prepare %d links in %.2fs", len(link_data_list), time.time() - _stage_t1) # Group the prepared NIO entries by destination compute and send # each compute a single /nios/batch request. @@ -1772,14 +1767,9 @@ class Project: ) if per_compute: - _stage_t2 = time.time() await asyncio.gather( *[_dispatch_batch(c, n) for c, n in per_compute.items()] ) - log.info( - "Project open stage timing: batch dispatch %d NIOs across %d compute(s) in %.2fs", - sum(len(n) for n in per_compute.values()), len(per_compute), time.time() - _stage_t2 - ) # Finalise every link: wire node/port back-references, mark created, # notify clients, and apply project-level marker definitions. From 4c6ef7752a5f37bc7c0375b4c4f0df7036c1aac7 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:16:32 +0800 Subject: [PATCH 10/32] log: emit progress lines for node and link loading on project open A large topology takes ~50s to open (dominated by docker daemon node creation). Without any start marker the user sees no feedback that work is in progress. Add two INFO lines: 'Loading N nodes...' before the node pool and 'Creating N links...' before the bulk link prepare/dispatch. --- gns3server/controller/project.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 587d734f9..eac1bb496 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1710,6 +1710,7 @@ class Project: # Create nodes in parallel with limited concurrency # to avoid overwhelming the system with too many simultaneous operations + log.info("Loading %d nodes...", len(nodes_to_create)) pool = Pool(concurrency=100) for compute, name, node_id, node_data in nodes_to_create: pool.append(self.add_node, compute, name, node_id, dump=False, **node_data) @@ -1732,6 +1733,7 @@ class Project: # request. This replaces one HTTP round-trip per link (~5000 for a # 2500-link topology) with one round-trip per compute. link_data_list = [d for d in topology.get("links", []) if "link_id" in d.keys()] + log.info("Creating %d links...", len(link_data_list)) sem = asyncio.Semaphore(100) async def _prepare_one(data): From df3ca6e26b7ccf6f94b6c33d2de38b64f53e07ac Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:22:26 +0800 Subject: [PATCH 11/32] log: lower per-node docker lifecycle logs to DEBUG At 1000+ nodes the per-node INFO lines flood the log during open / start-all / stop-all: MAC changed, adapters changed, created, started, console listen, fix ownership, stopped, paused, removed, adapter created, NIO removed, capture start/stop, CPU/memory limits, mount resources. Demote all of these routine per-node/per-adapter lines to DEBUG. Keep INFO only for genuinely rare/important events: image pull (missing image) and stale-container cleanup. Warnings unchanged. --- gns3server/compute/docker/docker_vm.py | 34 +++++++++++++------------- 1 file changed, 17 insertions(+), 17 deletions(-) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index 8358b4ed7..afc0fb665 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -229,7 +229,7 @@ class DockerVM(BaseNode): else: self._mac_address = mac_address - log.info('Docker container "{name}" [{id}]: MAC address changed to {mac_addr}'.format( + log.debug('Docker container "{name}" [{id}]: MAC address changed to {mac_addr}'.format( name=self._name, id=self._id, mac_addr=self._mac_address) @@ -349,7 +349,7 @@ class DockerVM(BaseNode): except OSError as e: raise DockerError(f"Cannot access resources: {e}") - log.info(f'Mount resources from "{resources_path}"') + log.debug(f'Mount resources from "{resources_path}"') binds = [{ "Type": "bind", "Source": resources_path, @@ -583,11 +583,11 @@ class DockerVM(BaseNode): log.error(f"Failed to clean up conflicting container '{self.docker_name}': {e}") raise self._cid = result["Id"] - log.info(f"Docker container '{self._name}' [{self._id}] created") + log.debug(f"Docker container '{self._name}' [{self._id}] created") if self._cpus > 0: - log.info(f"CPU limit set to {self._cpus} CPUs") + log.debug(f"CPU limit set to {self._cpus} CPUs") if self._memory > 0: - log.info(f"Memory limit set to {self._memory} MB") + log.debug(f"Memory limit set to {self._memory} MB") return True def _format_env(self, variables, env): @@ -705,7 +705,7 @@ class DockerVM(BaseNode): self._permissions_fixed = False self.status = "started" - log.info( + log.debug( "Docker container '{name}' [{image}] started listen for {console_type} on {console}".format( name=self._name, image=self._image, console=self.console, console_type=self.console_type ) @@ -751,7 +751,7 @@ class DockerVM(BaseNode): """ state = await self._get_container_state() - log.info(f"Docker container '{self._name}' fix ownership, state = {state}") + log.debug(f"Docker container '{self._name}' fix ownership, state = {state}") if state == "stopped" or state == "exited": # We need to restart it to fix permissions await self.manager.query("POST", f"containers/{self._cid}/start") @@ -1011,7 +1011,7 @@ class DockerVM(BaseNode): """ await self.manager.query("POST", f"containers/{self._cid}/restart") - log.info("Docker container '{name}' [{image}] restarted".format(name=self._name, image=self._image)) + log.debug("Docker container '{name}' [{image}] restarted".format(name=self._name, image=self._image)) async def _clean_servers(self): """ @@ -1056,7 +1056,7 @@ class DockerVM(BaseNode): # ignores SIGTERM — so a stop grace period buys nothing but latency. try: await self.manager.query("POST", f"containers/{self._cid}/kill") - log.info(f"Docker container '{self._name}' [{self._image}] stopped") + log.debug(f"Docker container '{self._name}' [{self._image}] stopped") except DockerHttp409Error: # Container is already stopped pass @@ -1073,7 +1073,7 @@ class DockerVM(BaseNode): await self.manager.query("POST", f"containers/{self._cid}/pause") self.status = "suspended" - log.info(f"Docker container '{self._name}' [{self._image}] paused") + log.debug(f"Docker container '{self._name}' [{self._image}] paused") async def unpause(self): """ @@ -1082,7 +1082,7 @@ class DockerVM(BaseNode): await self.manager.query("POST", f"containers/{self._cid}/unpause") self.status = "started" - log.info(f"Docker container '{self._name}' [{self._image}] unpaused") + log.debug(f"Docker container '{self._name}' [{self._image}] unpaused") async def close(self): """ @@ -1134,7 +1134,7 @@ class DockerVM(BaseNode): # Container deletion failed - log warning but don't block project close # The stale container will be cleaned up when the project is opened again log.warning(f"Failed to delete Docker container '{self.docker_name}': {e}") - log.info("Docker container '{name}' [{image}] removed".format(name=self._name, image=self._image)) + log.debug("Docker container '{name}' [{image}] removed".format(name=self._name, image=self._image)) if release_nio_udp_ports: for adapter in self._ethernet_adapters: @@ -1205,7 +1205,7 @@ class DockerVM(BaseNode): except UbridgeError as e: raise UbridgeNamespaceError(e) else: - log.info(f"Created adapter {adapter_number} with MAC address {mac_address} in namespace {self._namespace}") + log.debug(f"Created adapter {adapter_number} with MAC address {mac_address} in namespace {self._namespace}") if nio: await self._connect_nio(adapter_number, nio) @@ -1325,7 +1325,7 @@ class DockerVM(BaseNode): adapter.remove_nio(0) - log.info( + log.debug( "Docker VM '{name}' [{id}]: {nio} removed from adapter {adapter_number}".format( name=self.name, id=self.id, nio=adapter.host_ifc, adapter_number=adapter_number ) @@ -1382,7 +1382,7 @@ class DockerVM(BaseNode): for adapter_number in range(0, adapters): self._ethernet_adapters.append(EthernetAdapter()) - log.info( + log.debug( 'Docker container "{name}" [{id}]: number of Ethernet adapters changed to {adapters}'.format( name=self._name, id=self._id, adapters=adapters ) @@ -1439,7 +1439,7 @@ class DockerVM(BaseNode): if self.status == "started" and self.ubridge: await self._start_ubridge_capture(adapter_number, output_file) - log.info( + log.debug( "Docker VM '{name}' [{id}]: starting packet capture on adapter {adapter_number}".format( name=self.name, id=self.id, adapter_number=adapter_number ) @@ -1459,7 +1459,7 @@ class DockerVM(BaseNode): if self.status == "started" and self.ubridge: await self._stop_ubridge_capture(adapter_number) - log.info( + log.debug( "Docker VM '{name}' [{id}]: stopping packet capture on adapter {adapter_number}".format( name=self.name, id=self.id, adapter_number=adapter_number ) From 7dc66d48361f8376964aea185027d0bbf20cc038 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:30:33 +0800 Subject: [PATCH 12/32] fix: race in concurrent node creation sending duplicate POST /projects MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When opening a project, nodes are created with Pool(concurrency=100). Each _create_node did an unlocked check-then-act: 'if compute not in _project_created_on_compute' -> await POST /projects -> add(compute). The await let dozens of concurrent node creations race past the check before any registered, each firing a redundant POST /projects at the same compute. The compute-side sync handler then ran in a thread pool and instantiated the Project N times (the repeated 'Project ... created' INFO logs, ~16x). Guard the check+POST+register with a project-level asyncio.Lock. The first creation holds it for one POST; the rest acquire, see the compute already registered, and return immediately — negligible serialization. Also annotate the node/link progress logs with project name+id and add completion lines, so the log clearly shows which project is loading and when each phase finishes. --- gns3server/controller/project.py | 35 ++++++++++++++++++++++---------- 1 file changed, 24 insertions(+), 11 deletions(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index eac1bb496..4e1f0d9f3 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -160,6 +160,11 @@ class Project: self.dump() self._iou_id_lock = asyncio.Lock() + # Serialise the "ensure project exists on this compute" check in + # _create_node: without it, concurrent node creations all pass the + # `compute not in _project_created_on_compute` check before any has + # registered, and each fires a redundant POST /projects at the compute. + self._create_node_lock = asyncio.Lock() self._preallocated_udp_ports = {} # compute_id -> list of pre-allocated UDP ports log.debug(f'Project "{self.name}" [{self._id}] loaded') self.emit_controller_notification("project.created", self.asdict()) @@ -586,15 +591,21 @@ class Project: async def _create_node(self, compute, name, node_id, node_type=None, **kwargs): node = Node(self, compute, name, node_id=node_id, node_type=node_type, **kwargs) - if compute not in self._project_created_on_compute: - if compute.id == "local": - data = {"name": self._name, "project_id": self._id, "path": self._path} - else: - data = {"name": self._name, "project_id": self._id} - if self._variables: - data["variables"] = self._variables - await compute.post("/projects", data=data) - self._project_created_on_compute.add(compute) + # Hold the lock across the check + POST + register so that concurrent + # node creations on the same compute don't all race past the check and + # each POST /projects (the compute-side sync handler then instantiated + # the Project N times). Once one creation registers the compute, the + # rest see it in the set and return immediately. + async with self._create_node_lock: + if compute not in self._project_created_on_compute: + if compute.id == "local": + data = {"name": self._name, "project_id": self._id, "path": self._path} + else: + data = {"name": self._name, "project_id": self._id} + if self._variables: + data["variables"] = self._variables + await compute.post("/projects", data=data) + self._project_created_on_compute.add(compute) await node.create() self._nodes[node.id] = node @@ -1710,11 +1721,12 @@ class Project: # Create nodes in parallel with limited concurrency # to avoid overwhelming the system with too many simultaneous operations - log.info("Loading %d nodes...", len(nodes_to_create)) + log.info("Project '%s' [%s]: loading %d nodes...", self._name, self._id, len(nodes_to_create)) pool = Pool(concurrency=100) for compute, name, node_id, node_data in nodes_to_create: pool.append(self.add_node, compute, name, node_id, dump=False, **node_data) await pool.join() + log.info("Project '%s' [%s]: loaded %d nodes", self._name, self._id, len(nodes_to_create)) # Pre-allocate UDP ports for all links in batch to reduce HTTP round-trips ports_per_compute = {} for link_data in topology.get("links", []): @@ -1733,7 +1745,7 @@ class Project: # request. This replaces one HTTP round-trip per link (~5000 for a # 2500-link topology) with one round-trip per compute. link_data_list = [d for d in topology.get("links", []) if "link_id" in d.keys()] - log.info("Creating %d links...", len(link_data_list)) + log.info("Project '%s' [%s]: creating %d links...", self._name, self._id, len(link_data_list)) sem = asyncio.Semaphore(100) async def _prepare_one(data): @@ -1785,6 +1797,7 @@ class Project: await asyncio.gather( *[self.apply_defs_to_new_link(link) for link, _ in valid] ) + log.info("Project '%s' [%s]: created %d links", self._name, self._id, len(valid)) # Release any pre-allocated UDP ports that were not consumed by links for compute_id, ports in self._preallocated_udp_ports.items(): if ports: From 3aa39a2da34af322c98b096aa670eb49d37071eb Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:33:49 +0800 Subject: [PATCH 13/32] perf: raise start/stop/suspend/reset-console concurrency from 3 The historic concurrency=3 was far too conservative for 1000+ node topologies. Raise them based on operation weight: stop_all: 3 -> 100 (docker kill + permissions cleanup, light) suspend_all: 3 -> 50 (docker pause/unpause, light) start_all: 3 -> 20 (ubridge startup + docker start + network, heavy) reset_console: 3 -> 20 (terminal reset, light) Node creation (open) already uses concurrency=100 and approaches the container-create daemon limit (~20/s); stop/kill is substantially faster than create, so 100 is safe. --- gns3server/controller/project.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 4e1f0d9f3..176b721e5 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -2072,7 +2072,7 @@ class Project: """ Start all nodes (except always-running types like Ethernet switch, Cloud, NAT, etc.) """ - pool = Pool(concurrency=3) + pool = Pool(concurrency=20) for node in self.nodes.values(): if not node.is_always_running(): pool.append(node.start) @@ -2083,7 +2083,7 @@ class Project: """ Stop all nodes (except always-running types like Ethernet switch, Cloud, NAT, etc.) """ - pool = Pool(concurrency=3) + pool = Pool(concurrency=100) for node in self.nodes.values(): if not node.is_always_running(): pool.append(node.stop) @@ -2094,7 +2094,7 @@ class Project: """ Suspend all nodes """ - pool = Pool(concurrency=3) + pool = Pool(concurrency=50) for node in self.nodes.values(): pool.append(node.suspend) await pool.join() @@ -2105,7 +2105,7 @@ class Project: Reset console for all nodes """ - pool = Pool(concurrency=3) + pool = Pool(concurrency=20) for node in self.nodes.values(): pool.append(node.reset_console) await pool.join() From ec2a0ffff39bf91e8f177a76078ef2957cb4a5e8 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:39:49 +0800 Subject: [PATCH 14/32] log: lower per-node lifecycle logs in base_node to DEBUG The per-node created / is-closing / Starting-uBridge / Stopping-uBridge INFO lines flood the log at 1000+ node scale during project open, close, start-all and stop-all. Demote them to DEBUG (consistent with the docker_vm lifecycle-log demotion). --- gns3server/compute/base_node.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/gns3server/compute/base_node.py b/gns3server/compute/base_node.py index fc048892a..f4be58227 100644 --- a/gns3server/compute/base_node.py +++ b/gns3server/compute/base_node.py @@ -325,7 +325,7 @@ class BaseNode: Creates the node. """ - log.info("{module}: {name} [{id}] created".format(module=self.manager.module_name, name=self.name, id=self.id)) + log.debug("{module}: {name} [{id}] created".format(module=self.manager.module_name, name=self.name, id=self.id)) async def delete(self): """ @@ -374,7 +374,7 @@ class BaseNode: if self._closed: return False - log.info( + log.debug( "{module}: '{name}' [{id}]: is closing".format(module=self.manager.module_name, name=self.name, id=self.id) ) @@ -934,7 +934,7 @@ class BaseNode: self._ubridge_hypervisor = Hypervisor( self._project, self.ubridge_path, self.working_dir, transport, server_host, self.id ) - log.info(f"Starting new uBridge hypervisor at {self._ubridge_hypervisor.endpoint}") + log.debug(f"Starting new uBridge hypervisor at {self._ubridge_hypervisor.endpoint}") await self._ubridge_hypervisor.start() if self._ubridge_hypervisor: log.info( @@ -987,7 +987,7 @@ class BaseNode: """ if self._ubridge_hypervisor and self._ubridge_hypervisor.is_running(): - log.info(f"Stopping uBridge hypervisor at {self._ubridge_hypervisor.endpoint}") + log.debug(f"Stopping uBridge hypervisor at {self._ubridge_hypervisor.endpoint}") await self._ubridge_hypervisor.stop() self._ubridge_hypervisor = None # uBridge is gone, so every marker filter (and its in-bridge state) is From c366f2034089b4d57d597da19596650d6ddd1b05 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:48:13 +0800 Subject: [PATCH 15/32] log: add start/stop/close progress lines; revert start concurrency to 3 - start_all, stop_all: emit 'starting/stopping N nodes...' and complete lines with project name+id, matching the open-node/link log style. - close: emit 'project closing.../closed' bracketing the whole teardown. - Revert start_all concurrency 20->3 and reset_console 20->3: start (ubridge process + docker start + network) is heavy enough that high concurrency risks overwhelming the server. stop remains 100 (kill is light) and suspend remains 50 (pause is light). --- gns3server/controller/project.py | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 176b721e5..d92ad8155 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1372,6 +1372,7 @@ class Project: log.warning(f"Closing project '{self.name}' ignored because it is being loaded") return self._closing = True + log.info("Project '%s' [%s]: closing...", self._name, self._id) try: await self.stop_all() except HTTPException as e: @@ -1395,6 +1396,7 @@ class Project: self.reset() self._closing = False + log.info("Project '%s' [%s]: closed", self._name, self._id) def _clean_pictures(self): """ @@ -2072,22 +2074,30 @@ class Project: """ Start all nodes (except always-running types like Ethernet switch, Cloud, NAT, etc.) """ - pool = Pool(concurrency=20) - for node in self.nodes.values(): - if not node.is_always_running(): - pool.append(node.start) + nodes_to_start = [n for n in self.nodes.values() if not n.is_always_running()] + if not nodes_to_start: + return + log.info("Project '%s' [%s]: starting %d nodes...", self._name, self._id, len(nodes_to_start)) + pool = Pool(concurrency=3) + for node in nodes_to_start: + pool.append(node.start) await pool.join() + log.info("Project '%s' [%s]: started %d nodes", self._name, self._id, len(nodes_to_start)) @open_required async def stop_all(self): """ Stop all nodes (except always-running types like Ethernet switch, Cloud, NAT, etc.) """ + nodes_to_stop = [n for n in self.nodes.values() if not n.is_always_running()] + if not nodes_to_stop: + return + log.info("Project '%s' [%s]: stopping %d nodes...", self._name, self._id, len(nodes_to_stop)) pool = Pool(concurrency=100) - for node in self.nodes.values(): - if not node.is_always_running(): - pool.append(node.stop) + for node in nodes_to_stop: + pool.append(node.stop) await pool.join() + log.info("Project '%s' [%s]: stopped %d nodes", self._name, self._id, len(nodes_to_stop)) @open_required async def suspend_all(self): @@ -2105,7 +2115,7 @@ class Project: Reset console for all nodes """ - pool = Pool(concurrency=20) + pool = Pool(concurrency=3) for node in self.nodes.values(): pool.append(node.reset_console) await pool.join() From ed0f1bb4deed24e49aeb7142673042ddbadf91b0 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:54:53 +0800 Subject: [PATCH 16/32] fix: Dynamips create_nio(node, nio_settings) takes extra arg + add tests Dynamips.create_nio requires the node as first positional argument (unlike every other manager which takes only nio_settings). The batch handler now detects this via parameter-count inspection (3 vs 2) and passes node when needed. Also add Dynamips to _add_nio_binding dispatch: routers use slot_add_nio_binding(slot, port, nio), switches/hubs fall back to add_nio(nio, port_number). Add tests covering Dynamips router dispatch, switch dispatch, and the create_nio signature detection to prevent regression. --- gns3server/api/routes/compute/projects.py | 17 ++++++- tests/api/routes/compute/test_projects.py | 54 +++++++++++++++++++++++ 2 files changed, 70 insertions(+), 1 deletion(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index 5a4cb63fd..2a946c55a 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -21,6 +21,7 @@ API routes for projects. import os import shutil import urllib.parse +import inspect import logging @@ -149,6 +150,13 @@ async def _add_nio_binding(node, adapter_number, port_number, nio): await node.adapter_add_nio_binding(adapter_number, port_number, nio) elif manager_name == "VPCS": await node.port_add_nio_binding(port_number, nio) + elif manager_name == "Dynamips": + # Dynamips routers use slot_add_nio_binding(slot, port, nio); + # Dynamips switches/hubs use add_nio(nio, port_number). + if hasattr(node, "slot_add_nio_binding"): + await node.slot_add_nio_binding(adapter_number, port_number, nio) + else: + await node.add_nio(nio, port_number) elif manager_name == "Builtin": # ethernet_switch / ethernet_hub / cloud / nat: add_nio(nio, port_number) await node.add_nio(nio, port_number) @@ -180,7 +188,14 @@ async def create_batch_nios( added = 0 for entry in batch.nios: node = project.get_node(entry.node_id) - nio = node.manager.create_nio(jsonable_encoder(entry.nio, exclude_unset=True)) + nio_settings = jsonable_encoder(entry.nio, exclude_unset=True) + # Dynamips.create_nio takes an extra positional `node` argument that + # the base signature does not include. Detect it via parameter count. + sig = inspect.signature(node.manager.create_nio) + if len(sig.parameters) == 3: + nio = node.manager.create_nio(node, nio_settings) + else: + nio = node.manager.create_nio(nio_settings) await _add_nio_binding(node, entry.adapter_number, entry.port_number, nio) added += 1 return {"added": added} diff --git a/tests/api/routes/compute/test_projects.py b/tests/api/routes/compute/test_projects.py index 27474044b..28fa35bf4 100644 --- a/tests/api/routes/compute/test_projects.py +++ b/tests/api/routes/compute/test_projects.py @@ -224,3 +224,57 @@ class TestComputeProjectRoutes: project_id=project.id, file_path=file_path), content=b"world") assert response.status_code == status.HTTP_403_FORBIDDEN + + +class TestBatchNIOEdgeCases: + + @pytest.mark.asyncio + async def test_dynamips_router_dispatch_to_slot_add_nio_binding(self): + """_add_nio_binding dispatches Dynamips router to slot_add_nio_binding.""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "Dynamips" + node.slot_add_nio_binding = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 0, 0, nio) + node.slot_add_nio_binding.assert_called_once_with(0, 0, nio) + + @pytest.mark.asyncio + async def test_dynamips_switch_dispatch_to_add_nio(self): + """_add_nio_binding dispatches Dynamips switch to add_nio.""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "Dynamips" + del node.slot_add_nio_binding # no slot_add_nio → switch path + node.add_nio = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 0, 0, nio) + node.add_nio.assert_called_once_with(nio, 0) + + @pytest.mark.asyncio + async def test_dynamips_create_nio_passes_node_arg(self): + """ + Dynamips.create_nio(self, node, nio_settings) takes an extra 'node' + positional; the batch handler detects this via parameter count. + """ + import inspect + + # Dynamips-style 3-param signature (self + node + nio_settings) + async def create_nio_with_node(self, node, nio_settings): + pass + + sig = inspect.signature(create_nio_with_node) + assert len(sig.parameters) == 3 + + # Standard base 2-param signature (self + nio_settings) + async def create_nio_base(self, nio_settings): + pass + + sig2 = inspect.signature(create_nio_base) + assert len(sig2.parameters) == 2 From e56488c2f70c6c367374225a053db567e9289497 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:55:54 +0800 Subject: [PATCH 17/32] test: add _add_nio_binding dispatch tests for Qemu, IOU, VPCS, Builtin Cover every dispatch branch in the batch NIO endpoint so that future additions of node types with unusual NIO-binding signatures are caught at test time. --- tests/api/routes/compute/test_projects.py | 56 +++++++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/tests/api/routes/compute/test_projects.py b/tests/api/routes/compute/test_projects.py index 28fa35bf4..f491f3c04 100644 --- a/tests/api/routes/compute/test_projects.py +++ b/tests/api/routes/compute/test_projects.py @@ -278,3 +278,59 @@ class TestBatchNIOEdgeCases: sig2 = inspect.signature(create_nio_base) assert len(sig2.parameters) == 2 + + @pytest.mark.asyncio + async def test_qemu_dispatch_to_adapter_add_nio_binding(self): + """_add_nio_binding dispatches Qemu to adapter_add_nio_binding.""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "Qemu" + node.adapter_add_nio_binding = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 0, 0, nio) + node.adapter_add_nio_binding.assert_called_once_with(0, nio) + + @pytest.mark.asyncio + async def test_iou_dispatch_to_adapter_add_nio_binding(self): + """_add_nio_binding dispatches IOU to adapter_add_nio_binding(adapter, port, nio).""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "IOU" + node.adapter_add_nio_binding = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 1, 2, nio) + node.adapter_add_nio_binding.assert_called_once_with(1, 2, nio) + + @pytest.mark.asyncio + async def test_vpcs_dispatch_to_port_add_nio_binding(self): + """_add_nio_binding dispatches VPCS to port_add_nio_binding.""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "VPCS" + node.port_add_nio_binding = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 0, 3, nio) + node.port_add_nio_binding.assert_called_once_with(3, nio) + + @pytest.mark.asyncio + async def test_builtin_dispatch_to_add_nio(self): + """_add_nio_binding dispatches Builtin nodes to add_nio(nio, port).""" + from unittest.mock import AsyncMock, MagicMock + from gns3server.api.routes.compute.projects import _add_nio_binding + + node = MagicMock() + type(node.manager).__name__ = "Builtin" + node.add_nio = AsyncMock() + nio = MagicMock() + + await _add_nio_binding(node, 0, 0, nio) + node.add_nio.assert_called_once_with(nio, 0) From 09a9555d02f29361ecae1d72a9e9790043ab6b8d Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 00:58:08 +0800 Subject: [PATCH 18/32] fix: use bound-method param count for Dynamips create_nio detection MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The inspect check tested unbound function signatures (3 params unbound vs 2 unbound) but node.manager.create_nio is a bound method — inspect excludes 'self'. Dynamips bound = 2 (node + nio_settings), standard bound = 1 (nio_settings). The old '== 3' never matched, so the extra 'node' arg was never passed. Switch to '>= 2' and rewrite the test to exercise the actual bound-method scenario. --- gns3server/api/routes/compute/projects.py | 6 ++++- tests/api/routes/compute/test_projects.py | 27 ++++++++++++----------- 2 files changed, 19 insertions(+), 14 deletions(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index 2a946c55a..76c88d2f0 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -191,8 +191,12 @@ async def create_batch_nios( nio_settings = jsonable_encoder(entry.nio, exclude_unset=True) # Dynamips.create_nio takes an extra positional `node` argument that # the base signature does not include. Detect it via parameter count. + # Dynamips.create_nio(self, node, nio_settings) exposes one extra + # positional on the bound method compared to the standard signature + # (self, nio_settings). Detect it: standard == 1 bound param, + # Dynamips == 2 bound params (node + nio_settings). sig = inspect.signature(node.manager.create_nio) - if len(sig.parameters) == 3: + if len(sig.parameters) >= 2: nio = node.manager.create_nio(node, nio_settings) else: nio = node.manager.create_nio(nio_settings) diff --git a/tests/api/routes/compute/test_projects.py b/tests/api/routes/compute/test_projects.py index f491f3c04..b64053d7d 100644 --- a/tests/api/routes/compute/test_projects.py +++ b/tests/api/routes/compute/test_projects.py @@ -260,24 +260,25 @@ class TestBatchNIOEdgeCases: @pytest.mark.asyncio async def test_dynamips_create_nio_passes_node_arg(self): """ - Dynamips.create_nio(self, node, nio_settings) takes an extra 'node' - positional; the batch handler detects this via parameter count. + Dynamips.create_nio(self, node, nio_settings) exposes 2 bound-method + params vs. the standard 1. The batch handler detects this via the + parameter count on the bound method and passes the extra 'node' + argument. """ import inspect - # Dynamips-style 3-param signature (self + node + nio_settings) - async def create_nio_with_node(self, node, nio_settings): - pass + class _FakeDynamips: + async def create_nio(self, node, nio_settings): + pass - sig = inspect.signature(create_nio_with_node) - assert len(sig.parameters) == 3 + class _FakeBase: + async def create_nio(self, nio_settings): + pass - # Standard base 2-param signature (self + nio_settings) - async def create_nio_base(self, nio_settings): - pass - - sig2 = inspect.signature(create_nio_base) - assert len(sig2.parameters) == 2 + dyn = _FakeDynamips() + base = _FakeBase() + assert len(inspect.signature(dyn.create_nio).parameters) == 2 # Dynamips + assert len(inspect.signature(base.create_nio).parameters) == 1 # standard @pytest.mark.asyncio async def test_qemu_dispatch_to_adapter_add_nio_binding(self): From 4e30b6905a8d1b39d0f47d2742e0936146e533f7 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:00:01 +0800 Subject: [PATCH 19/32] fix: await Dynamips.create_nio (it is async, unlike sync base) Dynamips.create_nio is async def while BaseManager.create_nio is a sync def. The previous fix only added the extra 'node' argument but did not await the resulting coroutine, causing 'was never awaited' warnings and passing a coroutine object instead of an NIO instance to the binding dispatch. Add 'await' on the Dynamips branch. Test updated to verify both the async nature and the parameter count. --- gns3server/api/routes/compute/projects.py | 11 ++++------- tests/api/routes/compute/test_projects.py | 23 +++++++++++++++-------- 2 files changed, 19 insertions(+), 15 deletions(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index 76c88d2f0..ab55443fe 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -189,15 +189,12 @@ async def create_batch_nios( for entry in batch.nios: node = project.get_node(entry.node_id) nio_settings = jsonable_encoder(entry.nio, exclude_unset=True) - # Dynamips.create_nio takes an extra positional `node` argument that - # the base signature does not include. Detect it via parameter count. - # Dynamips.create_nio(self, node, nio_settings) exposes one extra - # positional on the bound method compared to the standard signature - # (self, nio_settings). Detect it: standard == 1 bound param, - # Dynamips == 2 bound params (node + nio_settings). + # Dynamips.create_nio(self, node, nio_settings) is async and takes an + # extra positional 'node'. Detect via bound-method parameter count: + # standard == 1, Dynamips == 2. Await the async variant. sig = inspect.signature(node.manager.create_nio) if len(sig.parameters) >= 2: - nio = node.manager.create_nio(node, nio_settings) + nio = await node.manager.create_nio(node, nio_settings) else: nio = node.manager.create_nio(nio_settings) await _add_nio_binding(node, entry.adapter_number, entry.port_number, nio) diff --git a/tests/api/routes/compute/test_projects.py b/tests/api/routes/compute/test_projects.py index b64053d7d..949c0d891 100644 --- a/tests/api/routes/compute/test_projects.py +++ b/tests/api/routes/compute/test_projects.py @@ -258,27 +258,34 @@ class TestBatchNIOEdgeCases: node.add_nio.assert_called_once_with(nio, 0) @pytest.mark.asyncio - async def test_dynamips_create_nio_passes_node_arg(self): + async def test_dynamips_create_nio_is_async_and_needs_await(self): """ - Dynamips.create_nio(self, node, nio_settings) exposes 2 bound-method - params vs. the standard 1. The batch handler detects this via the - parameter count on the bound method and passes the extra 'node' - argument. + Dynamips.create_nio is async (returns a coroutine) unlike the sync + base version. The batch handler must await it. """ import inspect + import asyncio as _asyncio class _FakeDynamips: async def create_nio(self, node, nio_settings): - pass + return {"type": "nio_udp", "node": node} class _FakeBase: - async def create_nio(self, nio_settings): - pass + def create_nio(self, nio_settings): + return {"type": "nio_udp"} dyn = _FakeDynamips() base = _FakeBase() assert len(inspect.signature(dyn.create_nio).parameters) == 2 # Dynamips assert len(inspect.signature(base.create_nio).parameters) == 1 # standard + assert inspect.iscoroutinefunction(dyn.create_nio) + assert not inspect.iscoroutinefunction(base.create_nio) + + # Verify the batch logic: 2 params → await, 1 param → no await + d_result = await dyn.create_nio("r1", {"type": "nio_udp"}) + b_result = base.create_nio({"type": "nio_udp"}) + assert d_result["node"] == "r1" + assert b_result["type"] == "nio_udp" @pytest.mark.asyncio async def test_qemu_dispatch_to_adapter_add_nio_binding(self): From f9f1a4d4d89a138c75427dcc11056185fd62d738 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:05:53 +0800 Subject: [PATCH 20/32] log: demote all per-node lifecycle INFO logs to DEBUG MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extend the docker_vm / base_node demotion to the remaining node types and supporting layers: qemu_vm: MAC, adapters, disk image, RAM, priority, NIO added, created iou_vm: application ID, adapters, serial, image, RAM, NIO added dynamips router: created, adapter, RAM, NVRAM, IOS, idle-PC, disk, MAC, NIO bound; hypervisor create/start/connect; nio_udp created builtin: ethernet_switch/hub, cloud, nat — created, NIO bound ubridge: hypervisor start/connect At multi-node scale these per-node lines flood the log. Only the project-open progress summary (loaded N nodes / creating N links) now remains at INFO alongside genuinely exceptional events. --- gns3server/api/routes/compute/qemu_nodes.py | 2 +- gns3server/compute/builtin/nodes/cloud.py | 12 +- .../compute/builtin/nodes/ethernet_hub.py | 2 +- .../compute/builtin/nodes/ethernet_switch.py | 12 +- gns3server/compute/builtin/nodes/nat.py | 2 +- gns3server/compute/dynamips/__init__.py | 6 +- .../compute/dynamips/dynamips_hypervisor.py | 4 +- gns3server/compute/dynamips/hypervisor.py | 8 +- gns3server/compute/dynamips/nios/nio_udp.py | 2 +- gns3server/compute/dynamips/nodes/router.py | 90 +++++++------- gns3server/compute/iou/iou_vm.py | 46 +++---- gns3server/compute/qemu/qemu_vm.py | 114 +++++++++--------- gns3server/compute/ubridge/hypervisor.py | 10 +- .../compute/ubridge/ubridge_hypervisor.py | 2 +- 14 files changed, 156 insertions(+), 156 deletions(-) diff --git a/gns3server/api/routes/compute/qemu_nodes.py b/gns3server/api/routes/compute/qemu_nodes.py index 51f8f60d8..efd6f7d74 100644 --- a/gns3server/api/routes/compute/qemu_nodes.py +++ b/gns3server/api/routes/compute/qemu_nodes.py @@ -83,7 +83,7 @@ async def create_qemu_node(project_id: UUID, node_data: schemas.QemuCreate) -> s for disk_index, drive in enumerate(drives): disk_image_backing_file = node_data.get(f"hd{drive}_disk_image_backing_file") if disk_image_backing_file: - log.info(f"Updating disk image for drive {drive} with backing file {disk_image_backing_file}") + log.debug(f"Updating disk image for drive {drive} with backing file {disk_image_backing_file}") node_data[f"hd{drive}_disk_image"] = disk_image_backing_file for name, value in node_data.items(): diff --git a/gns3server/compute/builtin/nodes/cloud.py b/gns3server/compute/builtin/nodes/cloud.py index 62cfb45ba..771a290c2 100644 --- a/gns3server/compute/builtin/nodes/cloud.py +++ b/gns3server/compute/builtin/nodes/cloud.py @@ -228,7 +228,7 @@ class Cloud(BaseNode): """ await self.start() - log.info(f'Cloud "{self._name}" [{self._id}] has been created') + log.debug(f'Cloud "{self._name}" [{self._id}] has been created') async def start(self): """ @@ -261,7 +261,7 @@ class Cloud(BaseNode): self.manager.port_manager.release_udp_port(nio.lport, self._project) await self._stop_ubridge() - log.info(f'Cloud "{self._name}" [{self._id}] has been closed') + log.debug(f'Cloud "{self._name}" [{self._id}] has been closed') async def _is_wifi_adapter_osx(self, adapter_name): """ @@ -429,7 +429,7 @@ class Cloud(BaseNode): if port_number in self._nios: raise NodeError(f"Port {port_number} isn't free") - log.info( + log.debug( 'Cloud "{name}" [{id}]: NIO {nio} bound to port {port}'.format( name=self._name, id=self._id, nio=nio, port=port_number ) @@ -485,7 +485,7 @@ class Cloud(BaseNode): if isinstance(nio, NIOUDP): self.manager.port_manager.release_udp_port(nio.lport, self._project) - log.info( + log.debug( 'Cloud "{name}" [{id}]: NIO {nio} removed from port {port}'.format( name=self._name, id=self._id, nio=nio, port=port_number ) @@ -535,7 +535,7 @@ class Cloud(BaseNode): await self._ubridge_send( 'bridge start_capture {name} "{output_file}"'.format(name=bridge_name, output_file=output_file) ) - log.info( + log.debug( "Cloud '{name}' [{id}]: starting packet capture on port {port_number}".format( name=self.name, id=self.id, port_number=port_number ) @@ -555,7 +555,7 @@ class Cloud(BaseNode): bridge_name = f"{self._id}-{port_number}" await self._ubridge_send(f"bridge stop_capture {bridge_name}") - log.info( + log.debug( "Cloud'{name}' [{id}]: stopping packet capture on port {port_number}".format( name=self.name, id=self.id, port_number=port_number ) diff --git a/gns3server/compute/builtin/nodes/ethernet_hub.py b/gns3server/compute/builtin/nodes/ethernet_hub.py index fc601ff01..4ef0e27e9 100644 --- a/gns3server/compute/builtin/nodes/ethernet_hub.py +++ b/gns3server/compute/builtin/nodes/ethernet_hub.py @@ -53,7 +53,7 @@ class EthernetHub(BaseNode): """ super().create() - log.info(f'Ethernet hub "{self._name}" [{self._id}] has been created') + log.debug(f'Ethernet hub "{self._name}" [{self._id}] has been created') async def delete(self): """ diff --git a/gns3server/compute/builtin/nodes/ethernet_switch.py b/gns3server/compute/builtin/nodes/ethernet_switch.py index a46366dd0..5c66cbad5 100644 --- a/gns3server/compute/builtin/nodes/ethernet_switch.py +++ b/gns3server/compute/builtin/nodes/ethernet_switch.py @@ -183,7 +183,7 @@ class EthernetSwitch(BaseNode): """ await self.start() - log.info(f'Ethernet switch "{self._name}" [{self._id}] has been created') + log.debug(f'Ethernet switch "{self._name}" [{self._id}] has been created') async def start(self): """ @@ -290,7 +290,7 @@ class EthernetSwitch(BaseNode): self._started = False await self._stop_ubridge() - log.info(f'Ethernet switch "{self._name}" [{self._id}] has been closed') + log.debug(f'Ethernet switch "{self._name}" [{self._id}] has been closed') return True # ------------------------------------------------------------------ # @@ -310,7 +310,7 @@ class EthernetSwitch(BaseNode): if not isinstance(nio, NIOUDP): raise NodeError("Ethernet switch ports only support UDP NIOs") - log.info( + log.debug( 'Ethernet switch "{name}" [{id}]: NIO {nio} bound to port {port}'.format( name=self._name, id=self._id, nio=nio, port=port_number ) @@ -397,7 +397,7 @@ class EthernetSwitch(BaseNode): if isinstance(nio, NIOUDP): self.manager.port_manager.release_udp_port(nio.lport, self._project) - log.info( + log.debug( 'Ethernet switch "{name}" [{id}]: NIO {nio} removed from port {port}'.format( name=self._name, id=self._id, nio=nio, port=port_number ) @@ -512,7 +512,7 @@ class EthernetSwitch(BaseNode): if self._ubridge_hypervisor and self._ubridge_hypervisor.is_running(): ubridge_bridge = self._ubridge_bridge_name(port_number) await self._ubridge_send(f'bridge start_capture {ubridge_bridge} "{output_file}"') - log.info( + log.debug( 'Ethernet switch "{name}" [{id}]: starting packet capture on port {port}'.format( name=self.name, id=self.id, port=port_number ) @@ -532,7 +532,7 @@ class EthernetSwitch(BaseNode): if self._ubridge_hypervisor and self._ubridge_hypervisor.is_running(): ubridge_bridge = self._ubridge_bridge_name(port_number) await self._ubridge_send(f"bridge stop_capture {ubridge_bridge}") - log.info( + log.debug( 'Ethernet switch "{name}" [{id}]: stopping packet capture on port {port}'.format( name=self.name, id=self.id, port=port_number ) diff --git a/gns3server/compute/builtin/nodes/nat.py b/gns3server/compute/builtin/nodes/nat.py index 31b96b9fe..a3b9b69d4 100644 --- a/gns3server/compute/builtin/nodes/nat.py +++ b/gns3server/compute/builtin/nodes/nat.py @@ -69,7 +69,7 @@ class Nat(Cloud): ) interface = interfaces[0] # take the first available interface containing the vmnet8 name - log.info(f"NAT node '{name}' configured to use NAT interface '{interface}'") + log.debug(f"NAT node '{name}' configured to use NAT interface '{interface}'") ports = [{"name": "nat0", "type": "ethernet", "interface": interface, "port_number": 0}] super().__init__(name, node_id, project, manager, ports=ports) diff --git a/gns3server/compute/dynamips/__init__.py b/gns3server/compute/dynamips/__init__.py index eeb4ed91f..134ce83e0 100644 --- a/gns3server/compute/dynamips/__init__.py +++ b/gns3server/compute/dynamips/__init__.py @@ -333,9 +333,9 @@ class Dynamips(BaseManager): port_manager = PortManager.instance() hypervisor = Hypervisor(self._dynamips_path, working_dir, server_host, port, port_manager.console_host, bind_console_host) - log.info(f"Creating new hypervisor {hypervisor.host}:{hypervisor.port} with working directory {working_dir}") + log.debug(f"Creating new hypervisor {hypervisor.host}:{hypervisor.port} with working directory {working_dir}") await hypervisor.start() - log.info(f"Hypervisor {hypervisor.host}:{hypervisor.port} has successfully started") + log.debug(f"Hypervisor {hypervisor.host}:{hypervisor.port} has successfully started") await hypervisor.connect() return hypervisor @@ -555,7 +555,7 @@ class Dynamips(BaseManager): :returns: relative path to the created config file """ - log.info(f"Creating config file {path}") + log.debug(f"Creating config file {path}") config_dir = os.path.dirname(path) try: os.makedirs(config_dir, exist_ok=True) diff --git a/gns3server/compute/dynamips/dynamips_hypervisor.py b/gns3server/compute/dynamips/dynamips_hypervisor.py index 187876eb2..997cfce60 100644 --- a/gns3server/compute/dynamips/dynamips_hypervisor.py +++ b/gns3server/compute/dynamips/dynamips_hypervisor.py @@ -90,12 +90,12 @@ class DynamipsHypervisor: if not connection_success: raise DynamipsError(f"Couldn't connect to hypervisor on {host}:{self._port} :{last_exception}") else: - log.info(f"Connected to Dynamips hypervisor on {host}:{self._port} after {time.time() - begin:.4f} seconds") + log.debug(f"Connected to Dynamips hypervisor on {host}:{self._port} after {time.time() - begin:.4f} seconds") try: version = await self.send("hypervisor version") self._version = version[0].split("-", 1)[0] - log.info("Dynamips version {} detected".format(self._version)) + log.debug("Dynamips version {} detected".format(self._version)) except IndexError: log.warning("Dynamips version could not be detected") self._version = "Unknown" diff --git a/gns3server/compute/dynamips/hypervisor.py b/gns3server/compute/dynamips/hypervisor.py index 517605f37..30d9a268b 100644 --- a/gns3server/compute/dynamips/hypervisor.py +++ b/gns3server/compute/dynamips/hypervisor.py @@ -120,14 +120,14 @@ class Hypervisor(DynamipsHypervisor): self._command = self._build_command() env = os.environ.copy() try: - log.info(f"Starting Dynamips: {self._command}") + log.debug(f"Starting Dynamips: {self._command}") self._stdout_file = os.path.join(self.working_dir, f"dynamips_i{self._id}_stdout.txt") - log.info(f"Dynamips process logging to {self._stdout_file}") + log.debug(f"Dynamips process logging to {self._stdout_file}") with open(self._stdout_file, "w", encoding="utf-8") as fd: self._process = await asyncio.create_subprocess_exec( *self._command, stdout=fd, stderr=subprocess.STDOUT, cwd=self._working_dir, env=env ) - log.info(f"Dynamips process started PID={self._process.pid}") + log.debug(f"Dynamips process started PID={self._process.pid}") self._started = True except (OSError, subprocess.SubprocessError) as e: log.error(f"Could not start Dynamips: {e}") @@ -139,7 +139,7 @@ class Hypervisor(DynamipsHypervisor): """ if self.is_running(): - log.info(f"Stopping Dynamips process PID={self._process.pid}") + log.debug(f"Stopping Dynamips process PID={self._process.pid}") await DynamipsHypervisor.stop(self) # give some time for the hypervisor to properly stop. # time to delete UNIX NIOs for instance. diff --git a/gns3server/compute/dynamips/nios/nio_udp.py b/gns3server/compute/dynamips/nios/nio_udp.py index d849a37bf..6a7590cbd 100644 --- a/gns3server/compute/dynamips/nios/nio_udp.py +++ b/gns3server/compute/dynamips/nios/nio_udp.py @@ -73,7 +73,7 @@ class NIOUDP(NIO): ) ) - log.info( + log.debug( "NIO UDP {name} created with lport={lport}, rhost={rhost}, rport={rport}".format( name=self._name, lport=self._lport, rhost=self._rhost, rport=self._rport ) diff --git a/gns3server/compute/dynamips/nodes/router.py b/gns3server/compute/dynamips/nodes/router.py index e6e750f83..6a09cae5f 100644 --- a/gns3server/compute/dynamips/nodes/router.py +++ b/gns3server/compute/dynamips/nodes/router.py @@ -126,7 +126,7 @@ class Router(BaseNode): self._dynamips_id = dynamips_id manager.take_dynamips_id(project.id, dynamips_id) else: - log.info("Creating a new ghost IOS instance") + log.debug("Creating a new ghost IOS instance") if self._console: # Ghost VMs do not need a console port. self.console = None @@ -243,7 +243,7 @@ class Router(BaseNode): if not self._ghost_flag: - log.info( + log.debug( 'Router {platform} "{name}" [{id}] has been created'.format( name=self._name, platform=self._platform, id=self._id ) @@ -328,7 +328,7 @@ class Router(BaseNode): ) await self._hypervisor.send(f'vm start "{self._name}"') self.status = "started" - log.info(f'router "{self._name}" [{self._id}] has been started') + log.debug(f'router "{self._name}" [{self._id}] has been started') self._memory_watcher = FileWatcher(self._memory_files(), self._memory_changed, strategy="hash", delay=30) monitor_process(self._hypervisor.process, self._termination_callback) @@ -348,7 +348,7 @@ class Router(BaseNode): if self.status == "started": self.status = "stopped" - log.info("Dynamips hypervisor process has stopped, return code: %d", returncode) + log.debug("Dynamips hypervisor process has stopped, return code: %d", returncode) if returncode != 0: self.project.emit( "log.error", @@ -369,7 +369,7 @@ class Router(BaseNode): except DynamipsError as e: log.warning(f"Could not stop {self._name}: {e}") self.status = "stopped" - log.info(f'Router "{self._name}" [{self._id}] has been stopped') + log.debug(f'Router "{self._name}" [{self._id}] has been stopped') if self._memory_watcher: self._memory_watcher.close() self._memory_watcher = None @@ -393,7 +393,7 @@ class Router(BaseNode): if status == "running": await self._hypervisor.send(f'vm suspend "{self._name}"') self.status = "suspended" - log.info(f'Router "{self._name}" [{self._id}] has been suspended') + log.debug(f'Router "{self._name}" [{self._id}] has been suspended') async def resume(self): """ @@ -404,7 +404,7 @@ class Router(BaseNode): if status == "suspended": await self._hypervisor.send(f'vm resume "{self._name}"') self.status = "started" - log.info(f'Router "{self._name}" [{self._id}] has been resumed') + log.debug(f'Router "{self._name}" [{self._id}] has been resumed') async def is_running(self): """ @@ -545,7 +545,7 @@ class Router(BaseNode): await self._hypervisor.send(f'vm set_ios "{self._name}" "{image}"') - log.info( + log.debug( 'Router "{name}" [{id}]: has a new IOS image set: "{image}"'.format( name=self._name, id=self._id, image=image ) @@ -574,7 +574,7 @@ class Router(BaseNode): return await self._hypervisor.send(f'vm set_ram "{self._name}" {ram}') - log.info( + log.debug( 'Router "{name}" [{id}]: RAM updated from {old_ram}MB to {new_ram}MB'.format( name=self._name, id=self._id, old_ram=self._ram, new_ram=ram ) @@ -602,7 +602,7 @@ class Router(BaseNode): return await self._hypervisor.send(f'vm set_nvram "{self._name}" {nvram}') - log.info( + log.debug( 'Router "{name}" [{id}]: NVRAM updated from {old_nvram}KB to {new_nvram}KB'.format( name=self._name, id=self._id, old_nvram=self._nvram, new_nvram=nvram ) @@ -635,9 +635,9 @@ class Router(BaseNode): await self._hypervisor.send(f'vm set_ram_mmap "{self._name}" {flag}') if mmap: - log.info(f'Router "{self._name}" [{self._id}]: mmap enabled') + log.debug(f'Router "{self._name}" [{self._id}]: mmap enabled') else: - log.info(f'Router "{self._name}" [{self._id}]: mmap disabled') + log.debug(f'Router "{self._name}" [{self._id}]: mmap disabled') self._mmap = mmap @property @@ -664,9 +664,9 @@ class Router(BaseNode): await self._hypervisor.send(f'vm set_sparse_mem "{self._name}" {flag}') if sparsemem: - log.info(f'Router "{self._name}" [{self._id}]: sparse memory enabled') + log.debug(f'Router "{self._name}" [{self._id}]: sparse memory enabled') else: - log.info(f'Router "{self._name}" [{self._id}]: sparse memory disabled') + log.debug(f'Router "{self._name}" [{self._id}]: sparse memory disabled') self._sparsemem = sparsemem @property @@ -688,7 +688,7 @@ class Router(BaseNode): """ await self._hypervisor.send(f'vm set_clock_divisor "{self._name}" {clock_divisor}') - log.info( + log.debug( 'Router "{name}" [{id}]: clock divisor updated from {old_clock} to {new_clock}'.format( name=self._name, id=self._id, old_clock=self._clock_divisor, new_clock=clock_divisor ) @@ -722,7 +722,7 @@ class Router(BaseNode): else: await self._hypervisor.send(f'vm set_idle_pc_online "{self._name}" 0 {idlepc}') - log.info(f'Router "{self._name}" [{self._id}]: idle-PC set to {idlepc}') + log.debug(f'Router "{self._name}" [{self._id}]: idle-PC set to {idlepc}') self._idlepc = idlepc async def get_idle_pc_prop(self): @@ -741,10 +741,10 @@ class Router(BaseNode): was_auto_started = True await asyncio.sleep(20) # leave time to the router to boot - log.info(f'Router "{self._name}" [{self._id}] has started calculating Idle-PC values') + log.debug(f'Router "{self._name}" [{self._id}] has started calculating Idle-PC values') begin = time.time() idlepcs = await self._hypervisor.send(f'vm get_idle_pc_prop "{self._name}" 0') - log.info( + log.debug( 'Router "{name}" [{id}] has finished calculating Idle-PC values after {time:.4f} seconds'.format( name=self._name, id=self._id, time=time.time() - begin ) @@ -789,7 +789,7 @@ class Router(BaseNode): if is_running: # router is running await self._hypervisor.send(f'vm set_idle_max "{self._name}" 0 {idlemax}') - log.info( + log.debug( 'Router "{name}" [{id}]: idlemax updated from {old_idlemax} to {new_idlemax}'.format( name=self._name, id=self._id, old_idlemax=self._idlemax, new_idlemax=idlemax ) @@ -820,7 +820,7 @@ class Router(BaseNode): 'vm set_idle_sleep_time "{name}" 0 {idlesleep}'.format(name=self._name, idlesleep=idlesleep) ) - log.info( + log.debug( 'Router "{name}" [{id}]: idlesleep updated from {old_idlesleep} to {new_idlesleep}'.format( name=self._name, id=self._id, old_idlesleep=self._idlesleep, new_idlesleep=idlesleep ) @@ -849,7 +849,7 @@ class Router(BaseNode): 'vm set_ghost_file "{name}" "{ghost_file}"'.format(name=self._name, ghost_file=ghost_file) ) - log.info( + log.debug( 'Router "{name}" [{id}]: ghost file set to "{ghost_file}"'.format( name=self._name, id=self._id, ghost_file=ghost_file ) @@ -892,7 +892,7 @@ class Router(BaseNode): 'vm set_ghost_status "{name}" {ghost_status}'.format(name=self._name, ghost_status=ghost_status) ) - log.info( + log.debug( 'Router "{name}" [{id}]: ghost status set to {ghost_status}'.format( name=self._name, id=self._id, ghost_status=ghost_status ) @@ -923,7 +923,7 @@ class Router(BaseNode): 'vm set_exec_area "{name}" {exec_area}'.format(name=self._name, exec_area=exec_area) ) - log.info( + log.debug( 'Router "{name}" [{id}]: exec area updated from {old_exec}MB to {new_exec}MB'.format( name=self._name, id=self._id, old_exec=self._exec_area, new_exec=exec_area ) @@ -949,7 +949,7 @@ class Router(BaseNode): await self._hypervisor.send(f'vm set_disk0 "{self._name}" {disk0}') - log.info( + log.debug( 'Router "{name}" [{id}]: disk0 updated from {old_disk0}MB to {new_disk0}MB'.format( name=self._name, id=self._id, old_disk0=self._disk0, new_disk0=disk0 ) @@ -975,7 +975,7 @@ class Router(BaseNode): await self._hypervisor.send(f'vm set_disk1 "{self._name}" {disk1}') - log.info( + log.debug( 'Router "{name}" [{id}]: disk1 updated from {old_disk1}MB to {new_disk1}MB'.format( name=self._name, id=self._id, old_disk1=self._disk1, new_disk1=disk1 ) @@ -1000,9 +1000,9 @@ class Router(BaseNode): """ if auto_delete_disks: - log.info(f'Router "{self._name}" [{self._id}]: auto delete disks enabled') + log.debug(f'Router "{self._name}" [{self._id}]: auto delete disks enabled') else: - log.info(f'Router "{self._name}" [{self._id}]: auto delete disks disabled') + log.debug(f'Router "{self._name}" [{self._id}]: auto delete disks disabled') self._auto_delete_disks = auto_delete_disks async def set_console(self, console): @@ -1130,7 +1130,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: MAC address updated from {old_mac} to {new_mac}'.format( name=self._name, id=self._id, old_mac=self._mac_addr, new_mac=mac_addr ) @@ -1160,7 +1160,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: system ID updated from {old_id} to {new_id}'.format( name=self._name, id=self._id, old_id=self._system_id, new_id=system_id ) @@ -1218,7 +1218,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: adapter {adapter} inserted into slot {slot_number}'.format( name=self._name, id=self._id, adapter=adapter, slot_number=slot_number ) @@ -1233,7 +1233,7 @@ class Router(BaseNode): 'vm slot_oir_start "{name}" {slot_number} 0'.format(name=self._name, slot_number=slot_number) ) - log.info( + log.debug( 'Router "{name}" [{id}]: OIR start event sent to slot {slot_number}'.format( name=self._name, id=self._id, slot_number=slot_number ) @@ -1279,7 +1279,7 @@ class Router(BaseNode): 'vm slot_oir_stop "{name}" {slot_number} 0'.format(name=self._name, slot_number=slot_number) ) - log.info( + log.debug( 'Router "{name}" [{id}]: OIR stop event sent to slot {slot_number}'.format( name=self._name, id=self._id, slot_number=slot_number ) @@ -1289,7 +1289,7 @@ class Router(BaseNode): 'vm slot_remove_binding "{name}" {slot_number} 0'.format(name=self._name, slot_number=slot_number) ) - log.info( + log.debug( 'Router "{name}" [{id}]: adapter {adapter} removed from slot {slot_number}'.format( name=self._name, id=self._id, adapter=adapter, slot_number=slot_number ) @@ -1331,7 +1331,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: {wic} inserted into WIC slot {wic_slot_number}'.format( name=self._name, id=self._id, wic=wic, wic_slot_number=wic_slot_number ) @@ -1375,7 +1375,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: {wic} removed from WIC slot {wic_slot_number}'.format( name=self._name, id=self._id, wic=adapter.wics[wic_slot_number], wic_slot_number=wic_slot_number ) @@ -1441,7 +1441,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: NIO {nio_name} bound to port {slot_number}/{port_number}'.format( name=self._name, id=self._id, nio_name=nio.name, slot_number=slot_number, port_number=port_number ) @@ -1502,7 +1502,7 @@ class Router(BaseNode): await nio.close() adapter.remove_nio(port_number) - log.info( + log.debug( 'Router "{name}" [{id}]: NIO {nio_name} removed from port {slot_number}/{port_number}'.format( name=self._name, id=self._id, nio_name=nio.name, slot_number=slot_number, port_number=port_number ) @@ -1526,7 +1526,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: NIO enabled on port {slot_number}/{port_number}'.format( name=self._name, id=self._id, slot_number=slot_number, port_number=port_number ) @@ -1581,7 +1581,7 @@ class Router(BaseNode): ) ) - log.info( + log.debug( 'Router "{name}" [{id}]: NIO disabled on port {slot_number}/{port_number}'.format( name=self._name, id=self._id, slot_number=slot_number, port_number=port_number ) @@ -1635,7 +1635,7 @@ class Router(BaseNode): ) ) await nio.start_packet_capture(output_file, data_link_type) - log.info( + log.debug( 'Router "{name}" [{id}]: starting packet capture on port {slot_number}/{port_number}'.format( name=self._name, id=self._id, nio_name=nio.name, slot_number=slot_number, port_number=port_number ) @@ -1675,7 +1675,7 @@ class Router(BaseNode): return await nio.stop_packet_capture() - log.info( + log.debug( 'Router "{name}" [{id}]: stopping packet capture on port {slot_number}/{port_number}'.format( name=self._name, id=self._id, nio_name=nio.name, slot_number=slot_number, port_number=port_number ) @@ -1748,7 +1748,7 @@ class Router(BaseNode): except OSError as e: raise DynamipsError(f"Could not amend the configuration {self.private_config_path}: {e}") - log.info(f'Router "{self._name}" [{self._id}]: renamed to "{new_name}"') + log.debug(f'Router "{self._name}" [{self._id}]: renamed to "{new_name}"') self._name = new_name async def extract_config(self): @@ -1788,7 +1788,7 @@ class Router(BaseNode): config = "!\n" + config.replace("\r", "") config_path = os.path.join(self._working_directory, startup_config) with open(config_path, "wb") as f: - log.info(f"saving startup-config to {startup_config}") + log.debug(f"saving startup-config to {startup_config}") f.write(config.encode("utf-8")) except (binascii.Error, OSError) as e: raise DynamipsError(f"Could not save the startup configuration {config_path}: {e}") @@ -1799,7 +1799,7 @@ class Router(BaseNode): config = base64.b64decode(private_config_base64).decode("utf-8", errors="replace") config_path = os.path.join(self._working_directory, private_config) with open(config_path, "wb") as f: - log.info(f"saving private-config to {private_config}") + log.debug(f"saving private-config to {private_config}") f.write(config.encode("utf-8")) except (binascii.Error, OSError) as e: raise DynamipsError(f"Could not save the private configuration {config_path}: {e}") @@ -1827,7 +1827,7 @@ class Router(BaseNode): await wait_run_in_executor(shutil.rmtree, self._working_directory) except OSError as e: log.warning(f"Could not delete file {e}") - log.info(f'Router "{self._name}" [{self._id}] has been deleted (including associated files)') + log.debug(f'Router "{self._name}" [{self._id}] has been deleted (including associated files)') def _memory_files(self): diff --git a/gns3server/compute/iou/iou_vm.py b/gns3server/compute/iou/iou_vm.py index edba56876..3893a6bd9 100644 --- a/gns3server/compute/iou/iou_vm.py +++ b/gns3server/compute/iou/iou_vm.py @@ -162,7 +162,7 @@ class IOUVM(BaseNode): super().__init__(name, node_id, project, manager, console=console, console_type=console_type) - log.info( + log.debug( 'IOU "{name}" [{id}]: assigned with application ID {application_id}'.format( name=self._name, id=self._id, application_id=application_id ) @@ -238,7 +238,7 @@ class IOUVM(BaseNode): self._path = self.manager.get_abs_image_path(path, self.project.path) self._loader = None - log.info(f'IOU "{self._name}" [{self._id}]: IOU image updated to "{self._path}"') + log.debug(f'IOU "{self._name}" [{self._id}]: IOU image updated to "{self._path}"') @property def use_default_iou_values(self): @@ -260,9 +260,9 @@ class IOUVM(BaseNode): self._use_default_iou_values = state if state: - log.info(f'IOU "{self._name}" [{self._id}]: uses the default IOU image values') + log.debug(f'IOU "{self._name}" [{self._id}]: uses the default IOU image values') else: - log.info(f'IOU "{self._name}" [{self._id}]: does not use the default IOU image values') + log.debug(f'IOU "{self._name}" [{self._id}]: does not use the default IOU image values') async def update_default_iou_values(self): """ @@ -430,7 +430,7 @@ class IOUVM(BaseNode): if self._ram == ram: return - log.info( + log.debug( 'IOU "{name}" [{id}]: RAM updated from {old_ram}MB to {new_ram}MB'.format( name=self._name, id=self._id, old_ram=self._ram, new_ram=ram ) @@ -459,7 +459,7 @@ class IOUVM(BaseNode): if self._nvram == nvram: return - log.info( + log.debug( 'IOU "{name}" [{id}]: NVRAM updated from {old_nvram}KB to {new_nvram}KB'.format( name=self._name, id=self._id, old_nvram=self._nvram, new_nvram=nvram ) @@ -574,7 +574,7 @@ class IOUVM(BaseNode): config = configparser.ConfigParser() try: - log.info(f"Checking IOU license in '{self.iourc_path}'") + log.debug(f"Checking IOU license in '{self.iourc_path}'") with open(self.iourc_path, encoding="utf-8") as f: config.read_file(f) except OSError as e: @@ -724,9 +724,9 @@ class IOUVM(BaseNode): await self._start_l1_keepalive_responder() try: if self._loader: - log.info(f"Starting IOU: {command} with loader {self._loader}") + log.debug(f"Starting IOU: {command} with loader {self._loader}") else: - log.info(f"Starting IOU: {command}") + log.debug(f"Starting IOU: {command}") self.command_line = " ".join(command) self._iou_process = await asyncio.create_subprocess_exec( *self._loader, *command, @@ -736,7 +736,7 @@ class IOUVM(BaseNode): cwd=self.working_dir, env=env, ) - log.info(f"IOU instance {self._id} started PID={self._iou_process.pid}") + log.debug(f"IOU instance {self._id} started PID={self._iou_process.pid}") self._started = True self.status = "started" callback = functools.partial(self._termination_callback, "IOU") @@ -920,7 +920,7 @@ class IOUVM(BaseNode): """ if self._iou_process: - log.info(f'Stopping IOU process for IOU VM "{self.name}" PID={self._iou_process.pid}') + log.debug(f'Stopping IOU process for IOU VM "{self.name}" PID={self._iou_process.pid}') try: self._iou_process.terminate() # Sometime the process can already be dead when we garbage collect @@ -979,7 +979,7 @@ class IOUVM(BaseNode): iou_id=self.application_id, ) ) - log.info("IOU {name} [id={id}]: NETMAP file created".format(name=self._name, id=self._id)) + log.debug("IOU {name} [id={id}]: NETMAP file created".format(name=self._name, id=self._id)) except OSError as e: raise IOUError(f"Could not create {netmap_path}: {e}") @@ -1030,7 +1030,7 @@ class IOUVM(BaseNode): ) self._l1_keepalive_transport = transport self._l1_keepalive_task = asyncio.create_task(self._send_l1_keepalives(protocol)) - log.info( + log.debug( 'IOU "%s" [%s]: L1 keepalive responder listening on %s', self._name, self._id, @@ -1150,7 +1150,7 @@ class IOUVM(BaseNode): for _ in range(0, ethernet_adapters): self._ethernet_adapters.append(EthernetAdapter(interfaces=4)) - log.info( + log.debug( 'IOU "{name}" [{id}]: number of Ethernet adapters changed to {adapters}'.format( name=self._name, id=self._id, adapters=len(self._ethernet_adapters) ) @@ -1180,7 +1180,7 @@ class IOUVM(BaseNode): for _ in range(0, serial_adapters): self._serial_adapters.append(SerialAdapter(interfaces=4)) - log.info( + log.debug( 'IOU "{name}" [{id}]: number of Serial adapters changed to {adapters}'.format( name=self._name, id=self._id, adapters=len(self._serial_adapters) ) @@ -1214,7 +1214,7 @@ class IOUVM(BaseNode): ) adapter.add_nio(port_number, nio) - log.info( + log.debug( 'IOU "{name}" [{id}]: {nio} added to {adapter_number}/{port_number}'.format( name=self._name, id=self._id, nio=nio, adapter_number=adapter_number, port_number=port_number ) @@ -1393,7 +1393,7 @@ class IOUVM(BaseNode): if isinstance(nio, NIOUDP): self.manager.port_manager.release_udp_port(nio.lport, self._project) adapter.remove_nio(port_number) - log.info( + log.debug( 'IOU "{name}" [{id}]: {nio} removed from {adapter_number}/{port_number}'.format( name=self._name, id=self._id, nio=nio, adapter_number=adapter_number, port_number=port_number ) @@ -1463,9 +1463,9 @@ class IOUVM(BaseNode): self._l1_keepalives = state if state: - log.info(f'IOU "{self._name}" [{self._id}]: has activated layer 1 keepalive messages') + log.debug(f'IOU "{self._name}" [{self._id}]: has activated layer 1 keepalive messages') else: - log.info(f'IOU "{self._name}" [{self._id}]: has deactivated layer 1 keepalive messages') + log.debug(f'IOU "{self._name}" [{self._id}]: has deactivated layer 1 keepalive messages') async def _enable_l1_keepalives(self, command): """ @@ -1700,7 +1700,7 @@ class IOUVM(BaseNode): try: config = startup_config_content.decode("utf-8", errors="replace") with open(config_path, "wb") as f: - log.info(f"saving startup-config to {config_path}") + log.debug(f"saving startup-config to {config_path}") f.write(config.encode("utf-8")) except (binascii.Error, OSError) as e: raise IOUError(f"Could not save the startup configuration {config_path}: {e}") @@ -1710,7 +1710,7 @@ class IOUVM(BaseNode): try: config = private_config_content.decode("utf-8", errors="replace") with open(config_path, "wb") as f: - log.info(f"saving private-config to {config_path}") + log.debug(f"saving private-config to {config_path}") f.write(config.encode("utf-8")) except (binascii.Error, OSError) as e: raise IOUError(f"Could not save the private configuration {config_path}: {e}") @@ -1734,7 +1734,7 @@ class IOUVM(BaseNode): ) nio.start_packet_capture(output_file, data_link_type) - log.info( + log.debug( 'IOU "{name}" [{id}]: starting packet capture on {adapter_number}/{port_number} to {output_file}'.format( name=self._name, id=self._id, @@ -1768,7 +1768,7 @@ class IOUVM(BaseNode): if not nio.capturing: return nio.stop_packet_capture() - log.info( + log.debug( 'IOU "{name}" [{id}]: stopping packet capture on {adapter_number}/{port_number}'.format( name=self._name, id=self._id, adapter_number=adapter_number, port_number=port_number ) diff --git a/gns3server/compute/qemu/qemu_vm.py b/gns3server/compute/qemu/qemu_vm.py index ce538d7f6..439523c65 100644 --- a/gns3server/compute/qemu/qemu_vm.py +++ b/gns3server/compute/qemu/qemu_vm.py @@ -187,7 +187,7 @@ class QemuVM(BaseNode): log.warning(f"Config disk: image '{self.config_disk_name}' missing") self.config_disk_name = "" - log.info(f'QEMU VM "{self._name}" [{self._id}] has been created') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has been created') @BaseNode.name.setter def name(self, new_name): @@ -270,7 +270,7 @@ class QemuVM(BaseNode): self._platform = re.sub(r'^qemu-system-(\w+).*$', r'\1', qemu_bin, flags=re.IGNORECASE) if self._platform.split(".")[0] not in list(QemuPlatform): raise QemuError(f"Platform {self._platform} is unknown") - log.info(f'QEMU VM "{self._name}" [{self._name}] has set the QEMU path to {qemu_path}') + log.debug(f'QEMU VM "{self._name}" [{self._name}] has set the QEMU path to {qemu_path}') def _check_qemu_path(self, qemu_path): @@ -292,7 +292,7 @@ class QemuVM(BaseNode): def platform(self, platform): self._platform = platform - log.info(f"QEMU VM '{self._name}' [{self._id}] has set the platform {platform}") + log.debug(f"QEMU VM '{self._name}' [{self._id}] has set the platform {platform}") self.qemu_path = f"qemu-system-{platform}" def _disk_setter(self, variable, value): @@ -311,7 +311,7 @@ class QemuVM(BaseNode): f"Sorry a node without the linked base setting enabled can only be used once on your server. {value} is already used by {node.name} in project {node.project.name}" ) setattr(self, "_" + variable, value) - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU {variable} path to {disk_image}'.format( name=self._name, variable=variable, id=self._id, disk_image=value ) @@ -416,7 +416,7 @@ class QemuVM(BaseNode): """ self._hda_disk_interface = hda_disk_interface - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU hda disk interface to {interface}'.format( name=self._name, id=self._id, interface=self._hda_disk_interface ) @@ -441,7 +441,7 @@ class QemuVM(BaseNode): """ self._hdb_disk_interface = hdb_disk_interface - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU hdb disk interface to {interface}'.format( name=self._name, id=self._id, interface=self._hdb_disk_interface ) @@ -466,7 +466,7 @@ class QemuVM(BaseNode): """ self._hdc_disk_interface = hdc_disk_interface - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU hdc disk interface to {interface}'.format( name=self._name, id=self._id, interface=self._hdc_disk_interface ) @@ -491,7 +491,7 @@ class QemuVM(BaseNode): """ self._hdd_disk_interface = hdd_disk_interface - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU hdd disk interface to {interface}'.format( name=self._name, id=self._id, interface=self._hdd_disk_interface ) @@ -518,7 +518,7 @@ class QemuVM(BaseNode): if cdrom_image: self._cdrom_image = self.manager.get_abs_image_path(cdrom_image, self.working_dir) - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU cdrom image path to {cdrom_image}'.format( name=self._name, id=self._id, cdrom_image=self._cdrom_image ) @@ -547,14 +547,14 @@ class QemuVM(BaseNode): self._cdrom_option() # this will check the cdrom image is accessible await self._control_vm("eject -f ide1-cd0") await self._control_vm(f"change ide1-cd0 {self._cdrom_image}") - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has changed the cdrom image path to {cdrom_image}'.format( name=self._name, id=self._id, cdrom_image=self._cdrom_image ) ) else: await self._control_vm("eject -f ide1-cd0") - log.info(f'QEMU VM "{self._name}" [{self._id}] has ejected the cdrom image') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has ejected the cdrom image') @property def bios_image(self): @@ -575,7 +575,7 @@ class QemuVM(BaseNode): """ self._bios_image = self.manager.get_abs_image_path(bios_image, self.working_dir) - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU bios image path to {bios_image}'.format( name=self._name, id=self._id, bios_image=self._bios_image ) @@ -600,7 +600,7 @@ class QemuVM(BaseNode): """ self._boot_priority = boot_priority - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the boot priority to {boot_priority}'.format( name=self._name, id=self._id, boot_priority=self._boot_priority ) @@ -635,7 +635,7 @@ class QemuVM(BaseNode): for adapter_number in range(0, adapters): self._ethernet_adapters.append(EthernetAdapter()) - log.info( + log.debug( 'QEMU VM "{name}" [{id}]: number of Ethernet adapters changed to {adapters}'.format( name=self._name, id=self._id, adapters=adapters ) @@ -661,7 +661,7 @@ class QemuVM(BaseNode): self._adapter_type = adapter_type - log.info( + log.debug( 'QEMU VM "{name}" [{id}]: adapter type changed to {adapter_type}'.format( name=self._name, id=self._id, adapter_type=adapter_type ) @@ -691,7 +691,7 @@ class QemuVM(BaseNode): else: self._mac_address = mac_address - log.info( + log.debug( 'QEMU VM "{name}" [{id}]: MAC address changed to {mac_addr}'.format( name=self._name, id=self._id, mac_addr=self._mac_address ) @@ -716,9 +716,9 @@ class QemuVM(BaseNode): """ if replicate_network_connection_state: - log.info(f'QEMU VM "{self._name}" [{self._id}] has enabled network connection state replication') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has enabled network connection state replication') else: - log.info(f'QEMU VM "{self._name}" [{self._id}] has disabled network connection state replication') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has disabled network connection state replication') self._replicate_network_connection_state = replicate_network_connection_state @property @@ -740,9 +740,9 @@ class QemuVM(BaseNode): """ if create_config_disk: - log.info(f'QEMU VM "{self._name}" [{self._id}] has enabled the config disk creation feature') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has enabled the config disk creation feature') else: - log.info(f'QEMU VM "{self._name}" [{self._id}] has disabled the config disk creation feature') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has disabled the config disk creation feature') self._create_config_disk = create_config_disk @property @@ -763,7 +763,7 @@ class QemuVM(BaseNode): :param on_close: string """ - log.info(f'QEMU VM "{self._name}" [{self._id}] set the close action to "{on_close}"') + log.debug(f'QEMU VM "{self._name}" [{self._id}] set the close action to "{on_close}"') self._on_close = on_close @property @@ -784,7 +784,7 @@ class QemuVM(BaseNode): :param cpu_throttling: integer """ - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the percentage of CPU allowed to {cpu}'.format( name=self._name, id=self._id, cpu=cpu_throttling ) @@ -812,7 +812,7 @@ class QemuVM(BaseNode): :param process_priority: string """ - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the process priority to {priority}'.format( name=self._name, id=self._id, priority=process_priority ) @@ -837,7 +837,7 @@ class QemuVM(BaseNode): :param ram: RAM amount in MB """ - log.info(f'QEMU VM "{self._name}" [{self._id}] has set the RAM to {ram}') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has set the RAM to {ram}') self._ram = ram @property @@ -858,7 +858,7 @@ class QemuVM(BaseNode): :param cpus: number of vCPUs. """ - log.info(f'QEMU VM "{self._name}" [{self._id}] has set the number of vCPUs to {cpus}') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has set the number of vCPUs to {cpus}') self._cpus = cpus @property @@ -879,7 +879,7 @@ class QemuVM(BaseNode): :param maxcpus: maximum number of hotpluggable vCPUs """ - log.info(f'QEMU VM "{self._name}" [{self._id}] has set maximum number of hotpluggable vCPUs to {maxcpus}') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has set maximum number of hotpluggable vCPUs to {maxcpus}') self._maxcpus = maxcpus @property @@ -901,9 +901,9 @@ class QemuVM(BaseNode): """ if tpm: - log.info(f'QEMU VM "{self._name}" [{self._id}] has enabled the Trusted Platform Module (TPM)') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has enabled the Trusted Platform Module (TPM)') else: - log.info(f'QEMU VM "{self._name}" [{self._id}] has disabled the Trusted Platform Module (TPM)') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has disabled the Trusted Platform Module (TPM)') self._tpm = tpm @property @@ -925,9 +925,9 @@ class QemuVM(BaseNode): """ if uefi: - log.info(f'QEMU VM "{self._name}" [{self._id}] has enabled the UEFI boot mode') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has enabled the UEFI boot mode') else: - log.info(f'QEMU VM "{self._name}" [{self._id}] has disabled the UEFI boot mode') + log.debug(f'QEMU VM "{self._name}" [{self._id}] has disabled the UEFI boot mode') self._uefi = uefi @property @@ -948,7 +948,7 @@ class QemuVM(BaseNode): :param options: QEMU options """ - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU options to {options}'.format( name=self._name, id=self._id, options=options ) @@ -996,7 +996,7 @@ class QemuVM(BaseNode): initrd = self.manager.get_abs_image_path(initrd, self.working_dir) - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU initrd path to {initrd}'.format( name=self._name, id=self._id, initrd=initrd ) @@ -1029,7 +1029,7 @@ class QemuVM(BaseNode): """ kernel_image = self.manager.get_abs_image_path(kernel_image, self.working_dir) - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU kernel image path to {kernel_image}'.format( name=self._name, id=self._id, kernel_image=kernel_image ) @@ -1054,7 +1054,7 @@ class QemuVM(BaseNode): :param kernel_command_line: QEMU kernel command line """ - log.info( + log.debug( 'QEMU VM "{name}" [{id}] has set the QEMU kernel command line to {kernel_command_line}'.format( name=self._name, id=self._id, kernel_command_line=kernel_command_line ) @@ -1114,7 +1114,7 @@ class QemuVM(BaseNode): command = [cpulimit_exec, "--lazy", "--pid={}".format(self._process.pid), "--limit={}".format(self._cpu_throttling)] self._cpulimit_process = subprocess.Popen(command, cwd=self.working_dir) - log.info(f"CPU throttled to {self._cpu_throttling}%") + log.debug(f"CPU throttled to {self._cpu_throttling}%") except FileNotFoundError: raise QemuError("cpulimit could not be found, please install it or deactivate CPU throttling") except (OSError, subprocess.SubprocessError) as e: @@ -1172,16 +1172,16 @@ class QemuVM(BaseNode): command = await self._build_command() command_string = " ".join(shlex.quote(s) for s in command) try: - log.info(f"Starting QEMU with: {command_string}") + log.debug(f"Starting QEMU with: {command_string}") self._stdout_file = os.path.join(self.working_dir, "qemu.log") - log.info(f"logging to {self._stdout_file}") + log.debug(f"logging to {self._stdout_file}") with open(self._stdout_file, "w", encoding="utf-8") as fd: fd.write(f"Start QEMU with {command_string}\n\nExecution log:\n") self.command_line = " ".join(command) self._process = await asyncio.create_subprocess_exec( *command, stdout=fd, stderr=subprocess.STDOUT, cwd=self.working_dir ) - log.info(f'QEMU VM "{self._name}" started PID={self._process.pid}') + log.debug(f'QEMU VM "{self._name}" started PID={self._process.pid}') self._command_line_changed = False self.status = "started" monitor_process(self._process, self._termination_callback) @@ -1242,7 +1242,7 @@ class QemuVM(BaseNode): """ if self.started: - log.info("QEMU process has stopped, return code: %d", returncode) + log.debug("QEMU process has stopped, return code: %d", returncode) await self.stop() if returncode != 0: qemu_stdout = self.read_stdout() @@ -1270,7 +1270,7 @@ class QemuVM(BaseNode): # stop the QEMU process self._hw_virtualization = False if self.is_running(): - log.info(f'Stopping QEMU VM "{self._name}" PID={self._process.pid}') + log.debug(f'Stopping QEMU VM "{self._name}" PID={self._process.pid}') try: if self.on_close == "save_vm_state": @@ -1498,7 +1498,7 @@ class QemuVM(BaseNode): self.status = "suspended" log.debug("QEMU VM has been suspended") else: - log.info(f"QEMU VM is not running to be suspended, current status is {vm_status}") + log.debug(f"QEMU VM is not running to be suspended, current status is {vm_status}") async def reload(self): """ @@ -1525,7 +1525,7 @@ class QemuVM(BaseNode): self.status = "started" log.debug("QEMU VM has been resumed") else: - log.info(f"QEMU VM is not paused to be resumed, current status is {vm_status}") + log.debug(f"QEMU VM is not paused to be resumed, current status is {vm_status}") async def adapter_add_nio_binding(self, adapter_number, nio): """ @@ -1559,7 +1559,7 @@ class QemuVM(BaseNode): ) adapter.add_nio(0, nio) - log.info( + log.debug( 'QEMU VM "{name}" [{id}]: {nio} added to adapter {adapter_number}'.format( name=self._name, id=self._id, nio=nio, adapter_number=adapter_number ) @@ -1619,7 +1619,7 @@ class QemuVM(BaseNode): self.manager.port_manager.release_udp_port(nio.lport, self._project) adapter.remove_nio(0) - log.info( + log.debug( 'QEMU VM "{name}" [{id}]: {nio} removed from adapter {adapter_number}'.format( name=self._name, id=self._id, nio=nio, adapter_number=adapter_number ) @@ -1671,7 +1671,7 @@ class QemuVM(BaseNode): ) ) - log.info( + log.debug( "QEMU VM '{name}' [{id}]: starting packet capture on adapter {adapter_number}".format( name=self.name, id=self.id, adapter_number=adapter_number ) @@ -1692,7 +1692,7 @@ class QemuVM(BaseNode): if self.ubridge: await self._ubridge_send("bridge stop_capture {name}".format(name=f"QEMU-{self._id}-{adapter_number}")) - log.info( + log.debug( "QEMU VM '{name}' [{id}]: stopping packet capture on adapter {adapter_number}".format( name=self.name, id=self.id, adapter_number=adapter_number ) @@ -1731,7 +1731,7 @@ class QemuVM(BaseNode): stdout = self.read_qemu_img_stdout() raise QemuError(f"Could not create '{disk_name}' disk image: qemu-img returned with {retcode}\n{stdout}") else: - log.info(f"QEMU VM '{self.name}' [{self.id}]: Qemu disk image'{disk_name}' created") + log.debug(f"QEMU VM '{self.name}' [{self.id}]: Qemu disk image'{disk_name}' created") except (OSError, subprocess.SubprocessError) as e: stdout = self.read_qemu_img_stdout() raise QemuError(f"Could not create '{disk_name}' disk image: {e}\n{stdout}") @@ -1759,7 +1759,7 @@ class QemuVM(BaseNode): stdout = self.read_qemu_img_stdout() raise QemuError(f"Could not update '{disk_name}' disk image: qemu-img returned with {retcode}\n{stdout}") else: - log.info(f"QEMU VM '{self.name}' [{self.id}]: Qemu disk image '{disk_name}' extended by {extend} MB") + log.debug(f"QEMU VM '{self.name}' [{self.id}]: Qemu disk image '{disk_name}' extended by {extend} MB") except (OSError, subprocess.SubprocessError) as e: stdout = self.read_qemu_img_stdout() raise QemuError(f"Could not update '{disk_name}' disk image: {e}\n{stdout}") @@ -1975,16 +1975,16 @@ class QemuVM(BaseNode): async def _qemu_img_exec(self, command): self._qemu_img_stdout_file = os.path.join(self.working_dir, "qemu-img.log") - log.info(f"logging to {self._qemu_img_stdout_file}") + log.debug(f"logging to {self._qemu_img_stdout_file}") command_string = " ".join(shlex.quote(s) for s in command) - log.info(f"Executing qemu-img with: {command_string}") + log.debug(f"Executing qemu-img with: {command_string}") with open(self._qemu_img_stdout_file, "w", encoding="utf-8") as fd: process = await asyncio.create_subprocess_exec( *command, stdout=fd, stderr=subprocess.STDOUT, cwd=self.working_dir ) retcode = await process.wait() if retcode != 0: - log.info(f"{self._get_qemu_img()} returned with {retcode}") + log.debug(f"{self._get_qemu_img()} returned with {retcode}") return retcode async def _find_disk_file_format(self, disk): @@ -2294,7 +2294,7 @@ class QemuVM(BaseNode): elif self._uefi: system_ovmf_firmware_dir = Path(self.manager.config.settings.Qemu.ovmf_firmware_dir) - log.info("Using OVMF firmware directory: {}".format(system_ovmf_firmware_dir)) + log.debug("Using OVMF firmware directory: {}".format(system_ovmf_firmware_dir)) old_ovmf_vars_path = os.path.join(self.working_dir, "OVMF_VARS.fd") if os.path.exists(old_ovmf_vars_path): # the node has its own UEFI variables store already, we must also use the old UEFI firmware @@ -2313,7 +2313,7 @@ class QemuVM(BaseNode): # otherwise, get the UEFI firmware from the images directory ovmf_firmware_path = self.manager.get_abs_image_path("OVMF_CODE_4M.fd") - log.info("Configuring UEFI boot mode using OVMF file: '{}'".format(ovmf_firmware_path)) + log.debug("Configuring UEFI boot mode using OVMF file: '{}'".format(ovmf_firmware_path)) options.extend(["-drive", "if=pflash,format=raw,readonly,file={}".format(ovmf_firmware_path)]) # try to use the UEFI variables store from the system first @@ -2397,9 +2397,9 @@ class QemuVM(BaseNode): "type=unixio,path={},terminate".format(tpm_sock) ] command_string = " ".join(shlex.quote(s) for s in command) - log.info("Starting swtpm (TPM emulator) with: {}".format(command_string)) + log.debug("Starting swtpm (TPM emulator) with: {}".format(command_string)) self._swtpm_process = subprocess.Popen(command, cwd=self.working_dir) - log.info("swtpm (TPM emulator) has started") + log.debug("swtpm (TPM emulator) has started") except (OSError, subprocess.SubprocessError) as e: raise QemuError("Could not start swtpm (TPM emulator): {}".format(e)) @@ -2587,7 +2587,7 @@ class QemuVM(BaseNode): stdout = self.read_qemu_img_stdout() log.warning(f"Could not delete saved VM state from disk {disk}: {stdout}") else: - log.info(f"Deleted saved VM state from disk {disk}") + log.debug(f"Deleted saved VM state from disk {disk}") except subprocess.SubprocessError as e: raise QemuError(f"Error while looking for the Qemu VM saved state snapshot: {e}") @@ -2617,7 +2617,7 @@ class QemuVM(BaseNode): if "snapshots" in json_data: for snapshot in json_data["snapshots"]: if snapshot["name"] == snapshot_name: - log.info( + log.debug( 'QEMU VM "{name}" [{id}] VM saved state detected (snapshot name: {snapshot})'.format( name=self._name, id=self.id, snapshot=snapshot_name ) diff --git a/gns3server/compute/ubridge/hypervisor.py b/gns3server/compute/ubridge/hypervisor.py index 89d815100..661da580c 100644 --- a/gns3server/compute/ubridge/hypervisor.py +++ b/gns3server/compute/ubridge/hypervisor.py @@ -180,15 +180,15 @@ class Hypervisor(UBridgeHypervisor): await self._check_ubridge_version(env) try: command = self._build_command() - log.info(f"starting ubridge: {command}") + log.debug(f"starting ubridge: {command}") self._stdout_file = os.path.join(self._working_dir, "ubridge.log") - log.info(f"logging to {self._stdout_file}") + log.debug(f"logging to {self._stdout_file}") with open(self._stdout_file, "w", encoding="utf-8") as fd: self._process = await asyncio.create_subprocess_exec( *command, stdout=fd, stderr=subprocess.STDOUT, cwd=self._working_dir, env=env ) - log.info(f"ubridge started PID={self._process.pid}") + log.debug(f"ubridge started PID={self._process.pid}") # An unsupported flag (e.g. -U on an old ubridge build) makes ubridge exit # immediately with a non-zero code. Detect that here and surface the real # reason from ubridge.log instead of waiting for connect() to time out with @@ -220,7 +220,7 @@ class Hypervisor(UBridgeHypervisor): log.error(error_msg) self._project.emit("log.error", {"message": error_msg}) else: - log.info("uBridge process has stopped, return code: %d", returncode) + log.debug("uBridge process has stopped, return code: %d", returncode) async def stop(self): """ @@ -228,7 +228,7 @@ class Hypervisor(UBridgeHypervisor): """ if self.is_running(): - log.info(f"Stopping uBridge process PID={self._process.pid}") + log.debug(f"Stopping uBridge process PID={self._process.pid}") await UBridgeHypervisor.stop(self) try: await wait_for_process_termination(self._process, timeout=3) diff --git a/gns3server/compute/ubridge/ubridge_hypervisor.py b/gns3server/compute/ubridge/ubridge_hypervisor.py index 68a84e477..2cbc3a7eb 100644 --- a/gns3server/compute/ubridge/ubridge_hypervisor.py +++ b/gns3server/compute/ubridge/ubridge_hypervisor.py @@ -103,7 +103,7 @@ class UBridgeHypervisor: if not connection_success: raise UbridgeError(f"Couldn't connect to hypervisor on {self.endpoint} :{last_exception}") else: - log.info(f"Connected to uBridge hypervisor on {self.endpoint} after {time.time() - begin:.4f} seconds") + log.debug(f"Connected to uBridge hypervisor on {self.endpoint} after {time.time() - begin:.4f} seconds") try: await asyncio.sleep(0.1) From 46bad0b63910f864ceeab7f1affe32e8d81a2ea4 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:10:18 +0800 Subject: [PATCH 21/32] fix: use socket.fromfd in send_batch_sync for Python 3.13 compat Python 3.13's asyncio TransportSocket wrapper rejects setblocking(). Dup the underlying fd via socket.fromfd() into a plain socket that the executor thread can drive in blocking mode, then detach() after the batch to avoid closing the transport's fd. --- gns3server/compute/ubridge/ubridge_hypervisor.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/gns3server/compute/ubridge/ubridge_hypervisor.py b/gns3server/compute/ubridge/ubridge_hypervisor.py index 2cbc3a7eb..009416d52 100644 --- a/gns3server/compute/ubridge/ubridge_hypervisor.py +++ b/gns3server/compute/ubridge/ubridge_hypervisor.py @@ -20,6 +20,7 @@ import logging import asyncio import threading import concurrent.futures +import socket as _socket from gns3server.utils.asyncio import locking from .ubridge_error import UbridgeError @@ -296,10 +297,15 @@ class UBridgeHypervisor: transport = self._writer.transport if transport is None or transport.is_closing(): raise UbridgeError("Transport closed") - sock = transport.get_extra_info("socket") - if sock is None: + tr_sock = transport.get_extra_info("socket") + if tr_sock is None: raise UbridgeError("No underlying socket for sync send_batch") + # Python 3.13's transport socket wrapper (trsock) rejects + # setblocking(), so dup the underlying fd into a plain socket + # that the executor thread can drive in blocking mode. + sock = _socket.fromfd(tr_sock.fileno(), tr_sock.family, _socket.SOCK_STREAM) + # Serialise access to this hypervisor's socket — only one batch (sync # or async) talks to uBridge at a time. The node-level async lock # (:func:`_ubridge_send`) is held for the entire executor call, so no @@ -343,3 +349,4 @@ class UBridgeHypervisor: self._recv_buf = b"" finally: sock.setblocking(False) + sock.detach() # release the dup'd fd, don't close transport From 2f70bd6daa4f30c1bd5057c2fd10bb526dddfa10 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:16:13 +0800 Subject: [PATCH 22/32] revert: drop _connect_nio thread-pool executor, restore async _ubridge_send MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The _connect_nio thread-pool optimisation (send_batch_sync) targeted node-start performance, but start_all already runs at concurrency=3 (by design, to avoid overwhelming the host). It also introduced a Python 3.13 incompatibility (trsock.setblocking forbidden) that prevented docker nodes from starting. Since node-start is not the target of this branch (project-open link creation is), revert to the simple per-command async _ubridge_send. The project-open batch NIO dispatch (create_batch_nios) is unaffected — it never called _connect_nio (nodes aren't started during open). --- gns3server/compute/docker/docker_vm.py | 46 +++------- .../compute/ubridge/ubridge_hypervisor.py | 84 ------------------- tests/compute/docker/test_docker_vm.py | 9 +- 3 files changed, 15 insertions(+), 124 deletions(-) diff --git a/gns3server/compute/docker/docker_vm.py b/gns3server/compute/docker/docker_vm.py index afc0fb665..ef4210668 100644 --- a/gns3server/compute/docker/docker_vm.py +++ b/gns3server/compute/docker/docker_vm.py @@ -38,7 +38,6 @@ from gns3server.utils.hostname import is_rfc1123_hostname_valid from gns3server.utils import macaddress_to_int, int_to_macaddress from gns3server.compute.ubridge.ubridge_error import UbridgeError, UbridgeNamespaceError -from gns3server.compute.ubridge.ubridge_hypervisor import _ubridge_sync_pool from ..base_node import BaseNode from ..adapters.ethernet_adapter import EthernetAdapter @@ -1218,40 +1217,19 @@ class DockerVM(BaseNode): async def _connect_nio(self, adapter_number, nio): bridge_name = f"bridge{adapter_number}" - - # Build the command batch for this NIO. We send everything in one - # executor call so that a single async-lock acquisition covers the - # whole batch, and different nodes' batches can overlap in the - # thread pool via blocking socket I/O. - commands = [ - f"bridge add_nio_udp {bridge_name} {nio.lport} {nio.rhost} {nio.rport}", - ] - if nio.capturing: - commands.append(f'bridge start_capture {bridge_name} "{nio.pcap_output_file}"') - commands.append(f"bridge start {bridge_name}") - commands.append(f"bridge reset_packet_filters {bridge_name}") - for packet_filter in self._build_filter_list(nio.filters): - commands.append(f"bridge add_packet_filter {bridge_name} {packet_filter}") - - # Hold the per-node ubridge lock across the entire executor batch so - # that no async _ubridge_send for this node can interleave with the - # sync socket writes. The lock is created lazily (mirrors the - # @locking decorator on _ubridge_send). - lock_name = "___ubridge_send_lock" - if not hasattr(self, lock_name): - setattr(self, lock_name, asyncio.Lock()) - async with getattr(self, lock_name): - loop = asyncio.get_running_loop() - await loop.run_in_executor( - _ubridge_sync_pool, # dedicated 500-worker thread pool - self._ubridge_hypervisor.send_batch_sync, - commands, + await self._ubridge_send( + "bridge add_nio_udp {bridge_name} {lport} {rhost} {rport}".format( + bridge_name=bridge_name, lport=nio.lport, rhost=nio.rhost, rport=nio.rport ) - - # Traffic-insight markers are rare — keep them on the async path so - # they benefit from the existing marker-management logic. The - # per-node lock is already released at this point, but markers - # serialise themselves via _ubridge_send's own @locking. + ) + if nio.capturing: + await self._ubridge_send( + 'bridge start_capture {bridge_name} "{pcap_file}"'.format( + bridge_name=bridge_name, pcap_file=nio.pcap_output_file + ) + ) + await self._ubridge_send(f"bridge start {bridge_name}") + await self._ubridge_apply_filters(bridge_name, nio.filters) await self._ubridge_apply_markers(bridge_name, nio) async def adapter_add_nio_binding(self, adapter_number, nio): diff --git a/gns3server/compute/ubridge/ubridge_hypervisor.py b/gns3server/compute/ubridge/ubridge_hypervisor.py index 009416d52..c010e1e2d 100644 --- a/gns3server/compute/ubridge/ubridge_hypervisor.py +++ b/gns3server/compute/ubridge/ubridge_hypervisor.py @@ -18,25 +18,12 @@ import re import time import logging import asyncio -import threading -import concurrent.futures -import socket as _socket from gns3server.utils.asyncio import locking from .ubridge_error import UbridgeError log = logging.getLogger(__name__) -# Dedicated thread pool for blocking ubridge socket I/O. Every node gets -# its own ubridge process + socket, so N nodes can send commands in true -# OS-thread parallelism. The default asyncio executor caps at ~32 threads; -# sizing for the large-topology case (2500+ links → thousands of NIO add -# calls across hundreds of nodes). -_ubridge_sync_pool = concurrent.futures.ThreadPoolExecutor( - max_workers=500, - thread_name_prefix="ubridge-sync", -) - class UBridgeHypervisor: @@ -70,8 +57,6 @@ class UBridgeHypervisor: self._timeout = timeout self._reader = None self._writer = None - self._recv_buf = b"" # leftover bytes from last sync recv - self._send_lock = threading.Lock() async def connect(self, timeout=10): """ @@ -281,72 +266,3 @@ class UBridgeHypervisor: log.debug(f"returned result {data}") return data - - def send_batch_sync(self, commands): - """ - Send multiple commands to uBridge using blocking socket I/O. Designed - to run inside ``loop.run_in_executor`` so that a single per-node batch - doesn't bounce through the event loop between every command, and - batches for *different* nodes run in parallel across the thread pool. - - :param commands: iterable of command strings - :raises UbridgeError: if any command fails - """ - if self._writer is None: - raise UbridgeError("Not connected") - transport = self._writer.transport - if transport is None or transport.is_closing(): - raise UbridgeError("Transport closed") - tr_sock = transport.get_extra_info("socket") - if tr_sock is None: - raise UbridgeError("No underlying socket for sync send_batch") - - # Python 3.13's transport socket wrapper (trsock) rejects - # setblocking(), so dup the underlying fd into a plain socket - # that the executor thread can drive in blocking mode. - sock = _socket.fromfd(tr_sock.fileno(), tr_sock.family, _socket.SOCK_STREAM) - - # Serialise access to this hypervisor's socket — only one batch (sync - # or async) talks to uBridge at a time. The node-level async lock - # (:func:`_ubridge_send`) is held for the entire executor call, so no - # async ``send()`` can interleave. - with self._send_lock: - sock.setblocking(True) - try: - for command in commands: - cmd = (command.strip() + "\n").encode() - sock.sendall(cmd) - - # Read until the terminating line (100-… or 2xx-…) - buf = self._recv_buf - while True: - try: - chunk = sock.recv(4096) - except BlockingIOError: - continue - if not chunk: - raise UbridgeError( - f"uBridge closed connection during '{command}'" - ) - buf += chunk - decoded = buf.decode("utf-8", errors="replace") - # Last complete line determines termination - tail = decoded.rsplit("\r\n", 1)[-1] - if tail and tail[0] in "12" and tail[1:3].isdigit() and len(tail) >= 4 and tail[3] == "-": - break - - # Check for error codes (2xx-…) - last_line = decoded.strip().split("\r\n")[-1] - if self.error_re.match(last_line): - raise UbridgeError(last_line[4:]) - - # Keep any leftover bytes (after the trailing \r\n) for the - # next read in the batch - trailer_start = decoded.rfind("\r\n") - if trailer_start >= 0: - self._recv_buf = buf[trailer_start + 2:] - else: - self._recv_buf = b"" - finally: - sock.setblocking(False) - sock.detach() # release the dup'd fd, don't close transport diff --git a/tests/compute/docker/test_docker_vm.py b/tests/compute/docker/test_docker_vm.py index ae40d91d9..c9e701306 100644 --- a/tests/compute/docker/test_docker_vm.py +++ b/tests/compute/docker/test_docker_vm.py @@ -1440,12 +1440,9 @@ async def test_add_ubridge_connection(vm): call.send('bridge create bridge0'), call.send("bridge add_nio_tap bridge0 tap-gns3-e0"), call.send('docker move_to_ns tap-gns3-e0 42 eth0'), - call.send_batch_sync([ - 'bridge add_nio_udp bridge0 4242 127.0.0.1 4343', - 'bridge start_capture bridge0 "/tmp/capture.pcap"', - 'bridge start bridge0', - 'bridge reset_packet_filters bridge0', - ]), + call.send('bridge add_nio_udp bridge0 4242 127.0.0.1 4343'), + call.send('bridge start_capture bridge0 "/tmp/capture.pcap"'), + call.send('bridge start bridge0'), ] assert 'bridge0' in vm._bridges # We need to check any_order otherwise mock is confused by asyncio From d84e75622821c8853a7c7c4f9eee27e2d7531630 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:20:14 +0800 Subject: [PATCH 23/32] tune: raise start_all concurrency from 3 to 10 3 is too conservative for modern hardware; 10 provides a moderate boost without the risk of overwhelming the host (start is the heaviest operation: ubridge process + docker start + network config for each node). --- gns3server/controller/project.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index d92ad8155..54ea44265 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -2078,7 +2078,7 @@ class Project: if not nodes_to_start: return log.info("Project '%s' [%s]: starting %d nodes...", self._name, self._id, len(nodes_to_start)) - pool = Pool(concurrency=3) + pool = Pool(concurrency=10) for node in nodes_to_start: pool.append(node.start) await pool.join() From c877ed87a62ccd03254ff95f7315038e1e75df26 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 08:29:39 +0800 Subject: [PATCH 24/32] log: add marker fan-out timing for project-open and interactive def-change Distinguish the two marker-policy fan-out paths in the log so we can tell which is slow: - apply_defs_to_new_link (project-open finalize): logs def count + link count + elapsed, only when marker_definitions is non-empty. - _marker_apply_concurrently (interactive create/update/delete def): logs link count + elapsed per fan-out. --- gns3server/controller/project.py | 23 ++++++++++++++++++++++- 1 file changed, 22 insertions(+), 1 deletion(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 54ea44265..965252428 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1260,6 +1260,14 @@ class Project: :param fail_msg: callable ``(link, error) -> log message`` """ + links = list(links) + if not links: + return + _t0 = time.time() + log.info( + "Project '%s' [%s]: fanning out marker operation to %d links...", + self._name, self._id, len(links) + ) sem = asyncio.Semaphore(32) async def guarded(link): @@ -1270,6 +1278,10 @@ class Project: log.warning(fail_msg(link, e)) await asyncio.gather(*(guarded(link) for link in links)) + log.info( + "Project '%s' [%s]: marker fan-out done in %.2fs", + self._name, self._id, time.time() - _t0 + ) @property def snapshots(self): @@ -1795,10 +1807,19 @@ class Project: n["port"].link = link link._created = True self.emit_notification("link.created", link.asdict()) - if valid: + if valid and self._marker_definitions: + _marker_t0 = time.time() + log.info( + "Project '%s' [%s]: applying %d marker definition(s) to %d links...", + self._name, self._id, len(self._marker_definitions), len(valid) + ) await asyncio.gather( *[self.apply_defs_to_new_link(link) for link, _ in valid] ) + log.info( + "Project '%s' [%s]: marker inheritance done in %.2fs", + self._name, self._id, time.time() - _marker_t0 + ) log.info("Project '%s' [%s]: created %d links", self._name, self._id, len(valid)) # Release any pre-allocated UDP ports that were not consumed by links for compute_id, ports in self._preallocated_udp_ports.items(): From 48991f2d29c21acfacd40f886e1a113290763ecd Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 08:44:57 +0800 Subject: [PATCH 25/32] perf: batch marker-def fan-out to one PUT /nios/batch per compute MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When a marker definition is created (or re-applied on data_link_type change), the fan-out used to call inherit_marker -> update() on every link, issuing one PUT /nio per link end (5000+ round-trips on a 2500-link project). On started nodes each round-trip also reconfigured uBridge. Two-phase fan-out: - inherit_marker/start_marker gain memory_only: writes the marker into link._markers and refreshes _link_data without any HTTP/emit/dump. - _apply_def_to_all_links applies memory-only to every link, then _batch_update_link_nios groups the updated NIO specs by compute and sends a single PUT /projects/{id}/nios/batch per compute. compute: new PUT /projects/{id}/nios/batch endpoint with _get_existing_nio + _update_nio_binding dispatch (mirrors create_batch_nios), re-applies filters+markers to uBridge on started nodes. Precise per-marker operations (update_marker bpf change, stop_marker on def delete) are untouched — they deliberately avoid a full reapply to preserve sibling marker pcaps. --- gns3server/api/routes/compute/projects.py | 90 +++++++++++++++++++++++ gns3server/controller/link.py | 3 +- gns3server/controller/project.py | 56 ++++++++++++-- gns3server/controller/udp_link.py | 28 ++++++- 4 files changed, 167 insertions(+), 10 deletions(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index ab55443fe..832892d5f 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -167,6 +167,65 @@ async def _add_nio_binding(node, adapter_number, port_number, nio): ) +def _get_existing_nio(node, adapter_number, port_number): + """ + Fetch the already-bound NIO for a port, preserving its UDP endpoints + (lport/rhost/rport) so a marker/filter update only changes markers/filters. + Dispatch keys off the manager class name, mirroring _add_nio_binding. + """ + + manager_name = type(node.manager).__name__ + if manager_name in ("Docker", "Qemu", "VMware", "VirtualBox"): + return node.get_nio(adapter_number) + elif manager_name == "IOU": + return node.get_nio(adapter_number, port_number) + elif manager_name in ("VPCS", "Builtin"): + return node.get_nio(port_number) + elif manager_name == "Dynamips": + # Dynamips routers expose NIOs via the slot/adapter; switches/hubs + # via get_nio(port). + if hasattr(node, "get_nio"): + import inspect as _inspect + if len(_inspect.signature(node.get_nio).parameters) >= 2: + return node.get_nio(adapter_number, port_number) + return node.get_nio(port_number) + raise HTTPException( + status_code=status.HTTP_400_BAD_REQUEST, + detail=f"Dynamips node '{node.name}' has no get_nio for batch update", + ) + raise HTTPException( + status_code=status.HTTP_400_BAD_REQUEST, + detail=f"Batch NIO update not supported for node type '{manager_name}'", + ) + + +async def _update_nio_binding(node, adapter_number, port_number, nio): + """ + Re-apply a NIO binding (filters + markers) to a started node's uBridge. + Dispatch keys off the manager class name, mirroring _add_nio_binding. + """ + + manager_name = type(node.manager).__name__ + if manager_name in ("Docker", "Qemu", "VMware", "VirtualBox"): + await node.adapter_update_nio_binding(adapter_number, nio) + elif manager_name == "IOU": + await node.adapter_update_nio_binding(adapter_number, port_number, nio) + elif manager_name == "VPCS": + await node.port_update_nio_binding(port_number, nio) + elif manager_name == "Dynamips": + if hasattr(node, "slot_update_nio_binding"): + await node.slot_update_nio_binding(adapter_number, port_number, nio) + else: + await node.update_nio(port_number, nio) + elif manager_name == "Builtin": + await node.update_nio(port_number, nio) + else: + raise HTTPException( + status_code=status.HTTP_400_BAD_REQUEST, + detail=f"Batch NIO update not supported for node type '{manager_name}'", + ) + + @router.post( "/projects/{project_id}/nios/batch", status_code=status.HTTP_201_CREATED, @@ -202,6 +261,37 @@ async def create_batch_nios( return {"added": added} +@router.put( + "/projects/{project_id}/nios/batch", + status_code=status.HTTP_200_OK, +) +async def update_batch_nios( + project_id: UUID, + batch: schemas.BatchNIOCreate, + project: Project = Depends(dep_project), +) -> dict: + """ + Update many NIO bindings (filters + markers) across nodes in a single + request, re-applying them to uBridge on started nodes. + + Used by the controller when a project-level marker definition changes and + must fan out to every affected link — replacing one PUT /nio round-trip per + link end with one round-trip per compute. Each entry fetches the already- + bound NIO (preserving its UDP endpoints), overlays the new markers/filters, + and re-binds it. + """ + + updated = 0 + for entry in batch.nios: + node = project.get_node(entry.node_id) + nio = _get_existing_nio(node, entry.adapter_number, entry.port_number) + nio.filters = entry.nio.filters or {} + nio.markers = entry.nio.markers or {} + await _update_nio_binding(node, entry.adapter_number, entry.port_number, nio) + updated += 1 + return {"updated": updated} + + @router.get("/projects/{project_id}/files", response_model=List[schemas.ProjectFile]) async def get_compute_project_files(project: Project = Depends(dep_project)) -> List[schemas.ProjectFile]: """ diff --git a/gns3server/controller/link.py b/gns3server/controller/link.py index 0cc00a140..d27fe80e8 100644 --- a/gns3server/controller/link.py +++ b/gns3server/controller/link.py @@ -114,7 +114,7 @@ class Link: """ return self._markers - async def inherit_marker(self, def_name, marker_def, dump=True): + async def inherit_marker(self, def_name, marker_def, dump=True, memory_only=False): """ Apply a project-level marker definition to this link. @@ -148,6 +148,7 @@ class Link: enabled=not marker_def.get("paused", False), inherited_from=def_name, dump=dump, + memory_only=memory_only, ) def _persist_markers(self): diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 965252428..12897eae3 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1210,17 +1210,57 @@ class Project: Fan out a single marker definition to every existing link in the project. Links that have no capable node (``_MARKER_CAPABLE_TYPES``) are silently skipped — the marker can only live on a uBridge bridge. + + Two-phase to avoid one HTTP round-trip per link end: (1) write the + inherited marker into each link's memory (``memory_only`` refreshes + ``_link_data`` without pushing), then (2) batch-update every affected + NIO via a single ``PUT /projects/{id}/nios/batch`` per compute. """ d = self._marker_definitions[def_name] - # dump=False: per-link topology writes are the dominant cost on large - # projects — the callers (create/update_marker_definition) dump once - # after the fan-out. - await self._marker_apply_concurrently( - list(self._links.values()), - lambda link: link.inherit_marker(def_name, d, dump=False), - lambda link, e: f"Marker definition '{def_name}' could not be applied to link {link.id}: {e}", - ) + affected = [] + for link in self._links.values(): + try: + await link.inherit_marker(def_name, d, dump=False, memory_only=True) + affected.append(link) + except ControllerError as e: + log.warning("Marker definition '%s' could not be applied to link %s: %s", def_name, link.id, e) + await self._batch_update_link_nios(affected) + + async def _batch_update_link_nios(self, links): + """ + Push the current ``_link_data`` (markers/filters) of *links* to their + computes in one ``PUT /projects/{id}/nios/batch`` per compute — replacing + one PUT /nio round-trip per link end. Started nodes re-apply uBridge; + stopped nodes update in memory. + """ + + per_compute = {} + for link in links: + if len(link._link_data) < 2: + continue + for i, side in enumerate(link._nodes): + node = side["node"] + per_compute.setdefault(node.compute, []).append( + { + "node_id": node.id, + "adapter_number": side["adapter_number"], + "port_number": side["port_number"], + "nio": link._link_data[i], + } + ) + + async def _dispatch(compute, entries): + await compute.put( + f"/projects/{self._id}/nios/batch", + data={"nios": entries}, + timeout=300, + ) + + if per_compute: + await asyncio.gather( + *[_dispatch(c, n) for c, n in per_compute.items()] + ) async def apply_defs_to_new_link(self, link): """ diff --git a/gns3server/controller/udp_link.py b/gns3server/controller/udp_link.py index 7e9517989..4b0bec4ec 100644 --- a/gns3server/controller/udp_link.py +++ b/gns3server/controller/udp_link.py @@ -407,7 +407,7 @@ class UDPLink(Link): # explicitly deletes a marker via the REST API, and a marker is torn # down automatically only when its link is deleted. - async def start_marker(self, name, bpf, tag=None, direction=None, data_link_type="DLT_EN10MB", capture_node_id=None, color=None, highlight_duration=None, enabled=True, inherited_from=None, dump=True): + async def start_marker(self, name, bpf, tag=None, direction=None, data_link_type="DLT_EN10MB", capture_node_id=None, color=None, highlight_duration=None, enabled=True, inherited_from=None, dump=True, memory_only=False): """ Attach a traffic-insight marker to this link. @@ -463,6 +463,12 @@ class UDPLink(Link): if inherited_from: marker_entry["inherited_from"] = inherited_from self._markers[name] = marker_entry + if memory_only: + # Project-open prepare / marker-def fan-out: only refresh the + # in-memory NIO specs so a later batch dispatch carries the new + # markers — no per-link update HTTP, notification or dump. + self._refresh_link_data() + return if self._created: await self.update() self._project.emit_notification("link.updated", self.asdict()) @@ -471,6 +477,26 @@ class UDPLink(Link): if dump: self._project.dump() + def _refresh_link_data(self): + """ + Recompute the filters / markers / suspend fields of ``_link_data`` from + the current link state without pushing to computes. Used by the + memory-only marker path so a batch dispatch picks up the new markers. + """ + + if len(self._link_data) < 2: + return + node1 = self._nodes[0]["node"] + node2 = self._nodes[1]["node"] + node1_filters, node2_filters = self._get_node_filters(node1, node2) + node1_markers, node2_markers = self._get_node_markers(node1, node2) + self._link_data[0]["filters"] = node1_filters + self._link_data[0]["markers"] = node1_markers + self._link_data[0]["suspend"] = self._suspended + self._link_data[1]["filters"] = node2_filters + self._link_data[1]["markers"] = node2_markers + self._link_data[1]["suspend"] = self._suspended + async def stop_marker(self, name, inherited=False, dump=True): """ Remove a traffic-insight marker from this link. From 57558508bf8e90a10ecbbcbbb458de7464933b47 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 08:53:44 +0800 Subject: [PATCH 26/32] perf: batch update/delete marker-def fan-out too (full project-level) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit per-def operations are project-level — create, update AND delete all modify the marker policy on every link — so all three must batch, not just create. Extend memory_only to update_marker and stop_marker (merge/delete into _markers + refresh _link_data, no per-link HTTP), and route update_marker_definition and delete_marker_definition through the same two-phase path as create: memory-only per link, then one PUT /projects/{id}/nios/batch per compute. Trade-off: a full reapply resets every marker's pcap on the link (the old precise update_marker/stop_marker preserved sibling pcaps). For project-level policy changes this is acceptable — real-time insight matters more than pcap continuity, and batching turns 5000+ round-trips into one per compute. --- .gitignore | 1 + gns3server/controller/project.py | 45 ++++++++++++++++--------------- gns3server/controller/udp_link.py | 17 ++++++++++-- 3 files changed, 40 insertions(+), 23 deletions(-) diff --git a/.gitignore b/.gitignore index 5d4619d10..7677a0718 100644 --- a/.gitignore +++ b/.gitignore @@ -86,3 +86,4 @@ venv gns3server/agent/gns3_copilot/cache/tiktoken/ gns3.log +/configs/ diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 12897eae3..c525473e0 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -1158,23 +1158,25 @@ class Project: # data_link_type decides which links host an inherited copy (serial # links are skipped unless a WAN encapsulation is chosen), so a change # needs a full re-fan-out: drop every copy, then re-apply. - await self._marker_apply_concurrently( - affected, - lambda link: link.stop_marker(f"global-{name}", inherited=True, dump=False), - lambda link, e: f"Failed to remove inherited marker global-{name} from link {link.id}: {e}", - ) + for link in affected: + try: + await link.stop_marker(f"global-{name}", inherited=True, dump=False, memory_only=True) + except ControllerError as e: + log.warning("Failed to remove inherited marker global-%s from link %s: %s", name, link.id, e) await self._apply_def_to_all_links(name) else: - # Sync: update every inherited copy across all links. - await self._marker_apply_concurrently( - affected, - lambda link: link.update_marker( - f"global-{name}", bpf=d["bpf"], tag=d.get("tag"), direction=d.get("direction"), - color=d.get("color"), highlight_duration=d.get("highlight_duration"), inherited=True, - dump=False - ), - lambda link, e: f"Failed to sync marker global-{name} on link {link.id}: {e}", - ) + # Sync: update every inherited copy across all links in memory, then + # batch-push to computes (one PUT /nios/batch per compute). + for link in affected: + try: + await link.update_marker( + f"global-{name}", bpf=d["bpf"], tag=d.get("tag"), direction=d.get("direction"), + color=d.get("color"), highlight_duration=d.get("highlight_duration"), inherited=True, + dump=False, memory_only=True + ) + except ControllerError as e: + log.warning("Failed to sync marker global-%s on link %s: %s", name, link.id, e) + await self._batch_update_link_nios(affected) self.dump() self.emit_notification("project.updated", self.asdict()) @@ -1195,12 +1197,13 @@ class Project: if f"global-{name}" in link.markers and link.markers[f"global-{name}"].get("inherited_from") == name ] - await self._marker_apply_concurrently( - affected, - lambda link: link.stop_marker(f"global-{name}", inherited=True), - # A missing compute or broken link shouldn't block the delete. - lambda link, e: f"Failed to remove inherited marker global-{name} from link {link.id}: {e}", - ) + for link in affected: + try: + await link.stop_marker(f"global-{name}", inherited=True, memory_only=True) + except ControllerError as e: + # A missing compute or broken link shouldn't block the delete. + log.warning("Failed to remove inherited marker global-%s from link %s: %s", name, link.id, e) + await self._batch_update_link_nios(affected) self.dump() self.emit_notification("project.updated", self.asdict()) diff --git a/gns3server/controller/udp_link.py b/gns3server/controller/udp_link.py index 4b0bec4ec..86f863010 100644 --- a/gns3server/controller/udp_link.py +++ b/gns3server/controller/udp_link.py @@ -497,7 +497,7 @@ class UDPLink(Link): self._link_data[1]["markers"] = node2_markers self._link_data[1]["suspend"] = self._suspended - async def stop_marker(self, name, inherited=False, dump=True): + async def stop_marker(self, name, inherited=False, dump=True, memory_only=False): """ Remove a traffic-insight marker from this link. @@ -522,6 +522,12 @@ class UDPLink(Link): capture_node_id = self._markers[name].get("capture_node_id") del self._markers[name] + if memory_only: + # Project-level def-delete fan-out: marker is gone from _markers; + # refresh _link_data so the batch dispatch drops it from uBridge + # via full reapply. No per-link delete round-trip, notification or dump. + self._refresh_link_data() + return # Remove the marker filter + its pcap on the capture node directly — NOT a # full NIO reapply (which would reset_packet_filters and close/reopen every # sibling marker's pcap). delete_packet_filter removes just this filter; @@ -541,7 +547,7 @@ class UDPLink(Link): if dump: self._project.dump() - async def update_marker(self, name, bpf=None, tag=None, enabled=None, direction=_UNSET, color=None, highlight_duration=None, inherited=False, dump=True): + async def update_marker(self, name, bpf=None, tag=None, enabled=None, direction=_UNSET, color=None, highlight_duration=None, inherited=False, dump=True, memory_only=False): """ Update an existing marker's fields and push to uBridge fine-grained — no full NIO reapply, so sibling markers' pcaps stay open. bpf/tag/direction @@ -590,6 +596,13 @@ class UDPLink(Link): if direction is not _UNSET: marker_info["direction"] = direction # None = clear back to both directions + if memory_only: + # Project-level def sync fan-out: state is already merged into + # _markers; just refresh _link_data so the batch dispatch carries + # it. No per-link uBridge rebuild, notification or dump. + self._refresh_link_data() + return + # Push to uBridge fine-grained — NO full NIO reapply (which would # reset_packet_filters and close/reopen every sibling marker's pcap): # * bpf/tag/direction changed → rebuild just this filter (delete + add), From e4d4282026d6d2f3f002450a50bbbb395a9f0baf Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 09:02:46 +0800 Subject: [PATCH 27/32] perf: parallelise compute-side batch NIO update per node The update_batch_nios handler looped serially across all entries (5010 for a 2505-link topology). On started nodes each entry does uBridge I/O, so the serial loop added orders of magnitude to the fan-out wall time. Group entries by node_id before dispatching. Different nodes talk to their own uBridge process (AF_UNIX socket) and are fully independent, so their updates run in parallel via asyncio.gather. Per-node entries are still serial (respecting the per-node uBridge command lock). --- gns3server/api/routes/compute/projects.py | 27 ++++++++++++++++------- 1 file changed, 19 insertions(+), 8 deletions(-) diff --git a/gns3server/api/routes/compute/projects.py b/gns3server/api/routes/compute/projects.py index 832892d5f..e09677f3e 100644 --- a/gns3server/api/routes/compute/projects.py +++ b/gns3server/api/routes/compute/projects.py @@ -22,6 +22,7 @@ import os import shutil import urllib.parse import inspect +import asyncio import logging @@ -281,15 +282,25 @@ async def update_batch_nios( and re-binds it. """ - updated = 0 + # Group entries by node so that different nodes' uBridge processes are + # updated in parallel (each node has its own AF_UNIX socket). Within a + # node entries are serial to respect the per-node uBridge command lock. + per_node = {} for entry in batch.nios: - node = project.get_node(entry.node_id) - nio = _get_existing_nio(node, entry.adapter_number, entry.port_number) - nio.filters = entry.nio.filters or {} - nio.markers = entry.nio.markers or {} - await _update_nio_binding(node, entry.adapter_number, entry.port_number, nio) - updated += 1 - return {"updated": updated} + per_node.setdefault(entry.node_id, []).append(entry) + + async def _update_one_node(node_id, entries): + node = project.get_node(node_id) + for e in entries: + nio = _get_existing_nio(node, e.adapter_number, e.port_number) + nio.filters = e.nio.filters or {} + nio.markers = e.nio.markers or {} + await _update_nio_binding(node, e.adapter_number, e.port_number, nio) + + await asyncio.gather( + *[_update_one_node(nid, ents) for nid, ents in per_node.items()] + ) + return {"updated": len(batch.nios)} @router.get("/projects/{project_id}/files", response_model=List[schemas.ProjectFile]) From 6c0ec30d5d3bd02cb05f8961c6af63d994a1b4fe Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 09:13:14 +0800 Subject: [PATCH 28/32] perf: move project-open marker inheritance to prepare phase MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously apply_defs_to_new_link ran during finalize (after link._created=True), issuing one PUT /nio round-trip per link end for each inherited marker — 5000+ HTTP round-trips even for a single def. Move it into _prepare_link_from_topology (memory_only) so the inherited markers are already in _link_data when _prepare() constructs the NIO specs, and create_batch_nios carries them in the single batch dispatch. Finalize no longer calls apply_defs_to_new_link. Interactive link creation (dragging a cable in the UI) still goes through the per-link create() → apply_defs_to_new_link path — a single link is fast. --- gns3server/controller/project.py | 22 +++++++++------------- 1 file changed, 9 insertions(+), 13 deletions(-) diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index c525473e0..566e49047 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -914,6 +914,15 @@ class Project: # a link should have 2 attached nodes, this can happen with corrupted projects await self.delete_link(link.id, force_delete=True) return None + # Apply project-level marker definitions onto the link's memory + # (memory_only) before _prepare() so the inherited markers ride the + # batch NIO dispatch — zero extra HTTP round-trips. The final + # apply_defs_to_new_link in finalize is removed. + for def_name, d in self._marker_definitions.items(): + try: + await link.inherit_marker(def_name, d, dump=False, memory_only=True) + except ControllerError as e: + log.warning("Marker definition '%s' could not be applied to link %s: %s", def_name, link.id, e) entries = await link._prepare() return (link, entries) @@ -1850,19 +1859,6 @@ class Project: n["port"].link = link link._created = True self.emit_notification("link.created", link.asdict()) - if valid and self._marker_definitions: - _marker_t0 = time.time() - log.info( - "Project '%s' [%s]: applying %d marker definition(s) to %d links...", - self._name, self._id, len(self._marker_definitions), len(valid) - ) - await asyncio.gather( - *[self.apply_defs_to_new_link(link) for link, _ in valid] - ) - log.info( - "Project '%s' [%s]: marker inheritance done in %.2fs", - self._name, self._id, time.time() - _marker_t0 - ) log.info("Project '%s' [%s]: created %d links", self._name, self._id, len(valid)) # Release any pre-allocated UDP ports that were not consumed by links for compute_id, ports in self._preallocated_udp_ports.items(): From a699383933f647519efa5fce0e9563e392d7e620 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 10:44:16 +0800 Subject: [PATCH 29/32] perf: raise marker UDP receive buffer from ~208KB to 8MB MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 1000+ uBridge processes share a single UDP marker.sink endpoint. The default kernel receive buffer (~208 KB) holds ~1000 datagrams — a traffic burst can overflow it before the event loop drains them. Grow it to 8 MB via setsockopt(SO_RCVBUF) so the kernel absorbs bursts without silent packet loss. UDP is unordered — buffer size does not affect per-datagram latency, only burst-loss resilience. --- gns3server/compute/marker/marker_manager.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/gns3server/compute/marker/marker_manager.py b/gns3server/compute/marker/marker_manager.py index 6ec128158..2dfea31a7 100644 --- a/gns3server/compute/marker/marker_manager.py +++ b/gns3server/compute/marker/marker_manager.py @@ -17,6 +17,7 @@ import asyncio import logging +import socket from gns3server.compute.marker.marker_listener import MarkerListener from gns3server.compute.notification_manager import NotificationManager @@ -75,10 +76,20 @@ class MarkerManager: return loop = asyncio.get_running_loop() self._listener = MarkerListener(self) + + def _configure_transport(transport): + sock = transport.get_extra_info("socket") + if sock is not None: + # Raise the UDP receive buffer from the default ~208 KB to 8 MB + # so that 1000+ uBridge processes can burst marker.match signals + # without kernel-side datagram loss. + sock.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 8 * 1024 * 1024) + try: self._transport, _ = await loop.create_datagram_endpoint( lambda: self._listener, local_addr=(host, port) ) + _configure_transport(self._transport) except OSError: if port != 0: log.warning( @@ -88,6 +99,7 @@ class MarkerManager: self._transport, _ = await loop.create_datagram_endpoint( lambda: self._listener, local_addr=(host, 0) ) + _configure_transport(self._transport) except OSError as e: log.error( "Marker listener startup failed: %s. Traffic insight signals are unavailable.", e From 2ac0bb7d259333fbf897407e6b2f22d1625435de Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Sun, 9 Aug 2026 00:54:51 +0800 Subject: [PATCH 30/32] marker: route marker.match to a dedicated project WS channel High-frequency marker.matches shared the single project notification queue with topology events (node.*/link.*), causing head-of-line blocking. Add a separate marker channel: Notification.project_marker_queue/marker_emit, dispatch routes marker.* off the main project queue, plus a new WS /{project_id}/notifications/markers/ws endpoint. Fully migrated (the main project WS no longer carries marker.match); marker listeners are independent of project auto_close. Compute side unchanged. --- gns3server/api/routes/controller/projects.py | 32 +++++++++++++++ gns3server/controller/notification.py | 42 ++++++++++++++++++++ tests/controller/test_notification.py | 27 +++++++++++++ 3 files changed, 101 insertions(+) diff --git a/gns3server/api/routes/controller/projects.py b/gns3server/api/routes/controller/projects.py index f9c838a34..d10de587a 100644 --- a/gns3server/api/routes/controller/projects.py +++ b/gns3server/api/routes/controller/projects.py @@ -485,6 +485,38 @@ async def project_ws_notifications( await project.close() +@router.websocket("/{project_id}/notifications/markers/ws") +async def project_marker_ws_notifications( + project_id: UUID, + websocket: WebSocket, + current_user: schemas.User = Depends(has_privilege_on_websocket("Project.Audit")) +) -> None: + """ + Receive marker notifications (e.g. marker.match) for a project on a + dedicated WebSocket, separate from the main project stream so high-frequency + marker.matches do not block topology events (node.*/link.*). + + Required privilege: Project.Audit + """ + + if current_user is None: + return + + controller = Controller.instance() + project = controller.get_project(str(project_id)) + + log.info(f"New client has connected to the marker notification stream for project ID '{project.id}' (WebSocket method)") + try: + with controller.notification.project_marker_queue(project.id) as queue: + while True: + notification = await queue.get_json(5) + await websocket.send_text(notification) + except (ConnectionClosed, WebSocketDisconnect): + log.info(f"Client has disconnected from the marker notification stream for project ID '{project.id}' (WebSocket method)") + except WebSocketException as e: + log.warning(f"Error while sending marker event to WebSocket client: {e}") + + @router.get("/{project_id}/export", dependencies=[Depends(has_privilege("Project.Audit"))]) async def export_project( project: Project = Depends(dep_project), diff --git a/gns3server/controller/notification.py b/gns3server/controller/notification.py index 3a63d9b87..d3540a746 100644 --- a/gns3server/controller/notification.py +++ b/gns3server/controller/notification.py @@ -31,6 +31,7 @@ class Notification: self._controller = controller self._project_listeners = {} + self._project_marker_listeners = {} self._controller_listeners = set() @contextmanager @@ -49,6 +50,26 @@ class Notification: finally: self._project_listeners[project_id].remove(queue) + @contextmanager + def project_marker_queue(self, project_id): + """ + Get a queue of marker notifications (marker.match etc.) for a project. + + Marker events are delivered on this dedicated channel instead of the + main project queue, so high-frequency marker.matches do not cause + head-of-line blocking for topology events (node.*/link.*). + + Use it with Python with + """ + + queue = NotificationQueue() + self._project_marker_listeners.setdefault(project_id, set()) + self._project_marker_listeners[project_id].add(queue) + try: + yield queue + finally: + self._project_marker_listeners[project_id].remove(queue) + @contextmanager def controller_queue(self): """ @@ -104,6 +125,8 @@ class Notification: elif action == "ping": event["compute_id"] = compute_id self.project_emit(action, event) + elif action.startswith("marker."): + self.marker_emit(action, event, project_id) else: self.project_emit(action, event, project_id) @@ -120,6 +143,25 @@ class Notification: else: self._send_event_to_all_projects(action, event) + def marker_emit(self, action, event, project_id): + """ + Send a marker notification (e.g. marker.match) to clients listening on + the dedicated marker channel for this project. Marker events are kept + off the main project queue on purpose, to avoid head-of-line blocking + from high-frequency matches. + + :param action: Action name + :param event: Event to send + :param project_id: Project id the marker belongs to + """ + + try: + marker_listeners = self._project_marker_listeners[project_id] + except KeyError: + return + for listener in marker_listeners: + asyncio.get_running_loop().call_soon_threadsafe(listener.put_nowait, (action, event, {})) + def _send_event_to_project(self, project_id, action, event): """ Send an event to all the client listening for notifications for diff --git a/tests/controller/test_notification.py b/tests/controller/test_notification.py index 9204acea3..754559154 100644 --- a/tests/controller/test_notification.py +++ b/tests/controller/test_notification.py @@ -120,6 +120,33 @@ async def test_dispatch_node_updated(controller, node, project): assert event["properties"]["startup_config"] == "ip 192" +@pytest.mark.asyncio +async def test_dispatch_marker_routed_to_marker_channel(controller, project): + """ + marker.* events are dispatched to the dedicated marker channel, not the + main project queue, so high-frequency matches cannot block topology events. + """ + + notif = controller.notification + with notif.project_queue(project.id) as project_q, \ + notif.project_marker_queue(project.id) as marker_q: + assert len(notif._project_marker_listeners[project.id]) == 1 + await project_q.get(0.1) # consume initial ping + await marker_q.get(0.1) # consume initial ping + + await notif.dispatch("marker.match", {"link_id": "abc"}, + project_id=project.id, compute_id=1) + + # marker.match lands on the marker channel... + msg = await marker_q.get(5) + assert msg == ('marker.match', {"link_id": "abc"}, {}) + # ...and does NOT land on the main project queue (times out -> ping) + msg = await project_q.get(0.1) + assert msg[0] == "ping" + + assert len(notif._project_marker_listeners[project.id]) == 0 + + def test_various_notification(controller, node): notif = controller.notification From 11461982b6981be244cab83c97a1b845a227e44d Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 11:40:22 +0800 Subject: [PATCH 31/32] log: add periodic marker.match throughput statistics MarkerManager now logs every 10s how many marker datagrams the UDP sink processed and the current throughput rate (match/s), so operators can tell at a glance whether the single sink keeps up with the aggregated uBridge traffic. Error count is also logged. --- gns3server/compute/marker/marker_listener.py | 4 ++++ gns3server/compute/marker/marker_manager.py | 21 ++++++++++++++++++++ 2 files changed, 25 insertions(+) diff --git a/gns3server/compute/marker/marker_listener.py b/gns3server/compute/marker/marker_listener.py index 2b5e5d47f..40cdd97b6 100644 --- a/gns3server/compute/marker/marker_listener.py +++ b/gns3server/compute/marker/marker_listener.py @@ -49,14 +49,18 @@ class MarkerListener(asyncio.DatagramProtocol): # MarkerManager owns this listener and the registry. self._manager = manager self.transport = None + self._received = 0 + self._errors = 0 def connection_made(self, transport): self.transport = transport def datagram_received(self, data, addr): + self._received += 1 try: self._handle(data) except Exception: + self._errors += 1 # Never let a malformed datagram kill the listener. log.exception("Failed to process MARK datagram from %s: %r", addr, data) diff --git a/gns3server/compute/marker/marker_manager.py b/gns3server/compute/marker/marker_manager.py index 2dfea31a7..711ea52e1 100644 --- a/gns3server/compute/marker/marker_manager.py +++ b/gns3server/compute/marker/marker_manager.py @@ -116,10 +116,31 @@ class MarkerManager: self._host = host self._port = sock.getsockname()[1] if sock else port log.info("Marker signal sink listening on %s:%s", self._host, self._port) + self._stats_task = asyncio.create_task(self._log_stats()) + + async def _log_stats(self): + """Log marker.match throughput every 10 s so operators can tell whether + the single UDP sink keeps up with the aggregated uBridge traffic.""" + while self.running: + await asyncio.sleep(10) + listener = self._listener + if listener is None: + break + received, errors = listener._received, listener._errors + rate = received / 10.0 if received else 0 + log.info( + "marker sink: %d matches (%.0f/s), %d errors in last 10s", + received, rate, errors, + ) + listener._received = 0 + listener._errors = 0 async def stop(self): """Close the UDP sink and drop the whole registry.""" + if hasattr(self, "_stats_task") and self._stats_task: + self._stats_task.cancel() + self._stats_task = None if self._transport: self._transport.close() self._transport = None From 04592a110720108f43723ef99ceca40d425ac9d7 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 11:43:43 +0800 Subject: [PATCH 32/32] log: suppress marker sink stats when no matches received --- gns3server/compute/marker/marker_manager.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/gns3server/compute/marker/marker_manager.py b/gns3server/compute/marker/marker_manager.py index 711ea52e1..132a19812 100644 --- a/gns3server/compute/marker/marker_manager.py +++ b/gns3server/compute/marker/marker_manager.py @@ -127,13 +127,13 @@ class MarkerManager: if listener is None: break received, errors = listener._received, listener._errors - rate = received / 10.0 if received else 0 - log.info( - "marker sink: %d matches (%.0f/s), %d errors in last 10s", - received, rate, errors, - ) listener._received = 0 listener._errors = 0 + if received: + log.info( + "marker sink: %d matches (%.0f/s), %d errors in last 10s", + received, received / 10.0, errors, + ) async def stop(self): """Close the UDP sink and drop the whole registry."""