From f9f1a4d4d89a138c75427dcc11056185fd62d738 Mon Sep 17 00:00:00 2001 From: YueGuobin Date: Tue, 11 Aug 2026 01:05:53 +0800 Subject: [PATCH] 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)