From 14917b7d562264d501fb989ca2e911fd1c3d4a9d Mon Sep 17 00:00:00 2001 From: Qubasa Date: Wed, 31 Jan 2024 16:13:32 +0700 Subject: [PATCH 1/2] Starting to implement logs --- .../clan_vm_manager/models/use_vms.py | 30 +++++++++++++++++-- .../clan_vm_manager/views/list.py | 3 +- 2 files changed, 30 insertions(+), 3 deletions(-) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py b/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py index 4be7aef6..ce77770b 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py @@ -1,5 +1,6 @@ import tempfile import weakref +from collections.abc import Generator from pathlib import Path from typing import Any, ClassVar @@ -110,9 +111,10 @@ class VM(GObject.Object): threading.Thread(target=self.__start).start() + self.connect("vm_status_changed", self._start_logs_task) + # Every 50ms check if the VM is still running self._watcher_id = GLib.timeout_add(50, self._vm_watcher_task) - if self._watcher_id == 0: log.error("Failed to add watcher") raise ClanError("Failed to add watcher") @@ -130,6 +132,21 @@ class VM(GObject.Object): return GLib.SOURCE_CONTINUE + def _start_logs_task(self, obj: Any, vm: Any, _vm: Any) -> None: + print("Starting log task") + self._logs_id = GLib.timeout_add(50, self._get_logs_task) + + def _get_logs_task(self) -> bool: + if not self.process.out_file.exists(): + log.error(f"Log file {self.process.out_file} does not exist") + return GLib.SOURCE_REMOVE + if not self.is_running(): + log.info("VM is not running") + return GLib.SOURCE_REMOVE + + print(self.read_whole_log()) + return GLib.SOURCE_CONTINUE + def is_running(self) -> bool: return self.process.proc.is_alive() @@ -144,7 +161,16 @@ class VM(GObject.Object): self.process.kill_group() - def read_log(self) -> str: + def read_line_log(self) -> Generator[str, None, None]: + with open(self.process.out_file) as f: + while True: + line = f.readline() + if not line: + break + yield line + return None + + def read_whole_log(self) -> str: if not self.process.out_file.exists(): log.error(f"Log file {self.process.out_file} does not exist") return "" diff --git a/pkgs/clan-vm-manager/clan_vm_manager/views/list.py b/pkgs/clan-vm-manager/clan_vm_manager/views/list.py index a14f9953..888882b6 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/views/list.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/views/list.py @@ -211,5 +211,6 @@ class ClanList(Gtk.Box): print("VM exited with code:", exitc) if not vm.is_running() and exitc != 0: print("VM exited with error. Exitcode:", exitc) - print(vm.read_log()) + print("==========VM LOGS=========") + print(vm.read_whole_log()) # self.show_error_dialog(vm.read_log()) From 16562946fe82c92779256d00cd15b3d501ef607c Mon Sep 17 00:00:00 2001 From: Qubasa Date: Fri, 2 Feb 2024 12:04:30 +0700 Subject: [PATCH 2/2] vm-manager: Added log console printing on vm start. Added python logging module --- pkgs/clan-cli/clan_cli/__init__.py | 4 +- pkgs/clan-cli/clan_cli/custom_logger.py | 4 +- pkgs/clan-cli/clan_cli/machines/machines.py | 4 +- .../clan_vm_manager/__init__.py | 15 ++++++ .../clan_vm_manager/errors/show_error.py | 5 +- .../clan_vm_manager/models/executor.py | 7 ++- .../clan_vm_manager/models/use_join.py | 5 +- .../clan_vm_manager/models/use_vms.py | 49 ++++++++++--------- .../clan_vm_manager/ui/__init__.py | 0 .../clan_vm_manager/views/list.py | 11 ++--- 10 files changed, 64 insertions(+), 40 deletions(-) delete mode 100644 pkgs/clan-vm-manager/clan_vm_manager/ui/__init__.py diff --git a/pkgs/clan-cli/clan_cli/__init__.py b/pkgs/clan-cli/clan_cli/__init__.py index 52b69b75..afc9adf3 100644 --- a/pkgs/clan-cli/clan_cli/__init__.py +++ b/pkgs/clan-cli/clan_cli/__init__.py @@ -117,10 +117,10 @@ def main() -> None: parser.print_help() if args.debug: - setup_logging(logging.DEBUG) + setup_logging(logging.DEBUG, root_log_name=__name__.split(".")[0]) log.debug("Debug log activated") else: - setup_logging(logging.INFO) + setup_logging(logging.INFO, root_log_name=__name__.split(".")[0]) if not hasattr(args, "func"): return diff --git a/pkgs/clan-cli/clan_cli/custom_logger.py b/pkgs/clan-cli/clan_cli/custom_logger.py index ea8a6609..9560f2f5 100644 --- a/pkgs/clan-cli/clan_cli/custom_logger.py +++ b/pkgs/clan-cli/clan_cli/custom_logger.py @@ -66,9 +66,9 @@ def get_caller() -> str: return ret -def setup_logging(level: Any) -> None: +def setup_logging(level: Any, root_log_name: str = __name__.split(".")[0]) -> None: # Get the root logger and set its level - main_logger = logging.getLogger("clan_cli") + main_logger = logging.getLogger(root_log_name) main_logger.setLevel(level) # Create and add the default handler diff --git a/pkgs/clan-cli/clan_cli/machines/machines.py b/pkgs/clan-cli/clan_cli/machines/machines.py index 69a5ef2b..aa7f3053 100644 --- a/pkgs/clan-cli/clan_cli/machines/machines.py +++ b/pkgs/clan-cli/clan_cli/machines/machines.py @@ -102,7 +102,6 @@ class Machine: system = config["system"] attr = f'clanInternals.machines."{system}".{self.name}.{attr}' - print(f"attr: {attr}") if attr in self.eval_cache and not refresh: return self.eval_cache[attr] @@ -115,9 +114,8 @@ class Machine: else: flake = self.flake - print(f"evaluating {flake}#{attr}") cmd = nix_eval([f"{flake}#{attr}"]) - print(f"cmd: {cmd}") + output = run(cmd).stdout.strip() self.eval_cache[attr] = output return output diff --git a/pkgs/clan-vm-manager/clan_vm_manager/__init__.py b/pkgs/clan-vm-manager/clan_vm_manager/__init__.py index 337fd79a..42560f4c 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/__init__.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/__init__.py @@ -1,15 +1,21 @@ import argparse +import logging from clan_cli.clan_uri import ClanURI +from clan_cli.custom_logger import setup_logging from clan_vm_manager.models.interfaces import ClanConfig from .app import MainApplication +log = logging.getLogger(__name__) + def main() -> None: parser = argparse.ArgumentParser(description="clan-vm-manager") + parser.add_argument("--debug", action="store_true", help="enable debug mode") + # Add join subcommand subparser = parser.add_subparsers( title="command", @@ -23,6 +29,15 @@ def main() -> None: # Executed when no command is given parser.set_defaults(func=show_overview) args = parser.parse_args() + + if args.debug: + setup_logging("DEBUG", root_log_name=__name__.split(".")[0]) + else: + setup_logging("INFO", root_log_name=__name__.split(".")[0]) + + log.debug("Debug logging enabled") + log.info("Info logging enabled") + args.func(args) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/errors/show_error.py b/pkgs/clan-vm-manager/clan_vm_manager/errors/show_error.py index f5ad364a..9c832d39 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/errors/show_error.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/errors/show_error.py @@ -1,5 +1,6 @@ #!/usr/bin/env python3 +import logging from typing import Literal import gi @@ -11,10 +12,12 @@ from gi.repository import Adw Severity = Literal["Error"] | Literal["Warning"] | Literal["Info"] | str +log = logging.getLogger(__name__) + def show_error_dialog(error: ClanError, severity: Severity | None = "Error") -> None: message = str(error) dialog = Adw.MessageDialog(parent=None, heading=severity, body=message) - print("error:", message) + log.error(message) dialog.add_response("ok", "ok") dialog.choose() diff --git a/pkgs/clan-vm-manager/clan_vm_manager/models/executor.py b/pkgs/clan-vm-manager/clan_vm_manager/models/executor.py index 4accb1b5..dfc56832 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/models/executor.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/models/executor.py @@ -1,3 +1,4 @@ +import logging import os import signal import sys @@ -14,6 +15,8 @@ import dataclasses import multiprocessing as mp from collections.abc import Callable +log = logging.getLogger(__name__) + # Kill the new process and all its children by sending a SIGTERM signal to the process group def _kill_group(proc: mp.Process) -> None: @@ -21,7 +24,7 @@ def _kill_group(proc: mp.Process) -> None: if proc.is_alive() and pid: os.killpg(pid, signal.SIGTERM) else: - print(f"Process {proc.name} with pid {pid} is already dead", file=sys.stderr) + log.warning(f"Process {proc.name} with pid {pid} is already dead") @dataclasses.dataclass(frozen=True) @@ -127,7 +130,7 @@ def spawn( # Print some information cmd = f"tail -f {out_file}" - print(f"Connect to stdout with: {cmd}") + log.info(f"Connect to stdout with: {cmd}") # Return the process mp_proc = MPProcess(name=proc_name, proc=proc, out_file=out_file) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/models/use_join.py b/pkgs/clan-vm-manager/clan_vm_manager/models/use_join.py index 86e0444d..b6458e0b 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/models/use_join.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/models/use_join.py @@ -1,3 +1,4 @@ +import logging from collections.abc import Callable from typing import Any @@ -12,6 +13,8 @@ gi.require_version("Gtk", "4.0") gi.require_version("Adw", "1") from gi.repository import Gio, GObject +log = logging.getLogger(__name__) + class JoinValue(GObject.Object): # TODO: custom signals for async join @@ -56,7 +59,7 @@ class Join: # TODO: remove the item that was accepted join from this list # and call the success function. (The caller is responsible for handling the success) try: - print(f"trying to join: {item.url}") + log.info(f"trying to join: {item.url}") history = add_history(item.url) cb(history) diff --git a/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py b/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py index ce77770b..5830ff5d 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/models/use_vms.py @@ -1,8 +1,8 @@ +import os import tempfile import weakref -from collections.abc import Generator from pathlib import Path -from typing import Any, ClassVar +from typing import IO, Any, ClassVar import gi from clan_cli import vms @@ -81,6 +81,8 @@ class VM(GObject.Object): self.data = data self.process = MPProcess("dummy", mp.Process(), Path("./dummy")) self._watcher_id: int = 0 + self._logs_id: int = 0 + self._log_file: IO[str] | None = None self.status = status self._last_liveness: bool = False self.log_dir = tempfile.TemporaryDirectory( @@ -116,7 +118,6 @@ class VM(GObject.Object): # Every 50ms check if the VM is still running self._watcher_id = GLib.timeout_add(50, self._vm_watcher_task) if self._watcher_id == 0: - log.error("Failed to add watcher") raise ClanError("Failed to add watcher") def _vm_watcher_task(self) -> bool: @@ -127,24 +128,38 @@ class VM(GObject.Object): # If the VM was running and now it is not, remove the watcher if prev_liveness and not self.is_running(): - print("===>Removing watcher") + log.debug("Removing VM watcher") return GLib.SOURCE_REMOVE - return GLib.SOURCE_CONTINUE - def _start_logs_task(self, obj: Any, vm: Any, _vm: Any) -> None: - print("Starting log task") - self._logs_id = GLib.timeout_add(50, self._get_logs_task) + def _start_logs_task(self, obj: Any, vm: Any) -> None: + if self.is_running(): + log.debug(f"Starting logs watcher on file: {self.process.out_file}") + self._logs_id = GLib.timeout_add(50, self._get_logs_task) + else: + log.debug("Not starting logs watcher") def _get_logs_task(self) -> bool: if not self.process.out_file.exists(): - log.error(f"Log file {self.process.out_file} does not exist") - return GLib.SOURCE_REMOVE + return GLib.SOURCE_CONTINUE + + if not self._log_file: + try: + self._log_file = open(self.process.out_file) + except Exception as ex: + log.exception(ex) + self._log_file = None + return GLib.SOURCE_REMOVE + if not self.is_running(): - log.info("VM is not running") + log.debug("Removing logs watcher") + self._log_file = None return GLib.SOURCE_REMOVE - print(self.read_whole_log()) + line = os.read(self._log_file.fileno(), 4096) + if len(line) != 0: + print(line.decode("utf-8"), end="", flush=True) + return GLib.SOURCE_CONTINUE def is_running(self) -> bool: @@ -156,20 +171,10 @@ class VM(GObject.Object): def stop(self) -> None: log.info("Stopping VM") if not self.is_running(): - log.error("VM already stopped") return self.process.kill_group() - def read_line_log(self) -> Generator[str, None, None]: - with open(self.process.out_file) as f: - while True: - line = f.readline() - if not line: - break - yield line - return None - def read_whole_log(self) -> str: if not self.process.out_file.exists(): log.error(f"Log file {self.process.out_file} does not exist") diff --git a/pkgs/clan-vm-manager/clan_vm_manager/ui/__init__.py b/pkgs/clan-vm-manager/clan_vm_manager/ui/__init__.py deleted file mode 100644 index e69de29b..00000000 diff --git a/pkgs/clan-vm-manager/clan_vm_manager/views/list.py b/pkgs/clan-vm-manager/clan_vm_manager/views/list.py index 888882b6..7341a235 100644 --- a/pkgs/clan-vm-manager/clan_vm_manager/views/list.py +++ b/pkgs/clan-vm-manager/clan_vm_manager/views/list.py @@ -1,3 +1,4 @@ +import logging from collections.abc import Callable from functools import partial @@ -12,6 +13,8 @@ from gi.repository import Adw, Gdk, Gio, GObject, Gtk from clan_vm_manager.models.use_vms import VM, VMS, ClanGroup, Clans +log = logging.getLogger(__name__) + def create_boxed_list( model: Gio.ListStore, render_row: Callable[[Gtk.ListBox, GObject], Gtk.Widget] @@ -194,8 +197,6 @@ class ClanList(Gtk.Box): self.join_boxed_list.add_css_class("no-shadow") def on_row_toggle(self, vm: VM, row: Adw.SwitchRow, state: bool) -> None: - print("Toggled", vm.data.flake.flake_attr, "active:", row.get_active()) - if row.get_active(): row.set_state(False) vm.start() @@ -208,9 +209,5 @@ class ClanList(Gtk.Box): switch.set_active(vm.is_running()) switch.set_state(vm.is_running()) exitc = vm.process.proc.exitcode - print("VM exited with code:", exitc) if not vm.is_running() and exitc != 0: - print("VM exited with error. Exitcode:", exitc) - print("==========VM LOGS=========") - print(vm.read_whole_log()) - # self.show_error_dialog(vm.read_log()) + log.error(f"VM exited with error. Exitcode: {exitc}")