Implement basic traceability for debugging

pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "simplyprint-ws-client"
-version = "1.0.0-rc.4"
+version = "1.0.0-rc.5"
 license = "AGPL-3.0-or-later"
 authors = ["SimplyPrint <[email protected]>"]
 description = "SimplyPrint Websocket Client"

simplyprint_ws_client/client/app.py

@@ -13,6 +13,7 @@
 from ..const import APP_DIRS
 from ..helpers.sentry import Sentry
 from ..helpers.url_builder import SimplyPrintUrl
+from ..utils import traceability
 from ..utils.event_loop_runner import EventLoopRunner
 
 
@@ -136,17 +137,18 @@ def add_new_client(self, config: Optional[Config]) -> asyncio.Future:
     def reload_client(self, client: Client) -> asyncio.Future:
         return asyncio.run_coroutine_threadsafe(self._reload_client(client), self.instance.event_loop)
 
-    def run_blocking(self):
+    def run_blocking(self, enable_tracing=False):
         with EventLoopRunner() as runner:
-            runner.run(self.run())
+            with traceability.enable_traceable(enable_tracing):
+                runner.run(self.run())
 
-    def run_detached(self):
+    def run_detached(self, *args, **kwargs):
         """ Run the client in a separate thread. """
         if self.instance_thread:
             self.logger.warning("Client instance already running - stopping old instance")
             self.stop()
 
-        self.instance_thread = threading.Thread(target=self.run_blocking)
+        self.instance_thread = threading.Thread(target=self.run_blocking, args=args, kwargs=kwargs)
         self.instance_thread.start()
 
     def stop(self):

simplyprint_ws_client/client/client.py

@@ -14,6 +14,7 @@
 from ..helpers.intervals import IntervalTypes, Intervals
 from ..helpers.physical_machine import PhysicalMachine
 from ..utils.event_loop_provider import EventLoopProvider
+from ..utils.traceability import traceable
 
 
 class ClientConfigurationException(Exception):
@@ -75,14 +76,12 @@ def __init__(
         # Recover handles from the class
         # TODO: Generalize this under the event system.
         for name in dir(self):
-            if not hasattr(self, name):
-                continue
-
-            attr = getattr(self, name)
-
-            if hasattr(attr, "_event"):
-                event_cls = attr._event
-                self.event_bus.on(event_cls, attr, attr._pre)
+            try:
+                attr = getattr(self, name)
+                event_cls = getattr(attr, "_event")
+                self.event_bus.on(event_cls, attr, getattr(attr, "_pre"))
+            except (AttributeError, RuntimeError):
+                pass
 
     async def __aenter__(self):
         """ Acquire a client to perform order sensitive operations."""
@@ -94,13 +93,15 @@ async def __aexit__(self, exc_type, exc, tb):
         self._client_lock.release()
 
     @property
+    @traceable(with_retval=True, with_stack=True)
     def connected(self) -> bool:
         """
         Check if the client is connected to the server.
         """
-        return self._connected
+        return self._connected and self.is_external_connected()
 
     @connected.setter
+    @traceable(with_args=True, with_stack=True)
     def connected(self, value: bool):
         self._connected = value
 
@@ -146,6 +147,13 @@ def set_ui_info(self, ui: str, ui_version: str):
         self.printer.info.ui = ui
         self.printer.info.ui_version = ui_version
 
+    def is_external_connected(self):
+        """
+        Check if the client is connected to an external device.
+        """
+
+        return True
+
     @abstractmethod
     async def init(self):
         """

simplyprint_ws_client/client/lifetime/lifetime_manager.py

@@ -1,11 +1,15 @@
 import logging
 from enum import Enum
-from typing import Dict
+from typing import Dict, TYPE_CHECKING
 
 from .lifetime import ClientLifetime, ClientAsyncLifetime
 from ..client import Client
+from ...utils import traceability
 from ...utils.stoppable import AsyncStoppable
 
+if TYPE_CHECKING:
+    from ..instance import Instance
+
 
 class LifetimeType(Enum):
     ASYNC = 0
@@ -22,11 +26,15 @@ def get_cls(self):
 class LifetimeManager(AsyncStoppable):
     logger: logging.Logger
     lifetime_check_interval = 10
+
+    instance: 'Instance'
     lifetimes: Dict[Client, ClientLifetime]
 
-    def __init__(self, *args, **kwargs):
+    def __init__(self, instance: 'Instance', *args, **kwargs):
         super().__init__(*args, **kwargs)
-        self.logger = logging.getLogger("lifetime_manager")
+
+        self.logger = instance.logger.getChild("lifetime_manager")
+        self.instance = instance
         self.lifetimes = {}
 
     def contains(self, client: Client) -> bool:
@@ -55,13 +63,21 @@ async def loop(self) -> None:
                 if lifetime.is_stopped():
                     continue
 
-                if lifetime.is_healthy():
+                if not lifetime.is_healthy():
+                    client.logger.warning(f"Client lifetime unhealthy - restarting")
+                    await self.restart_lifetime(client)
                     continue
 
-                client.logger.warning(f"Client lifetime unhealthy - restarting")
+                if self.instance.connection.is_connected() and not client._connected:
+                    connected_trace = traceability.from_class(client).get("connected", None)
 
-                await self.stop_lifetime(client)
-                await self.start_lifetime(client)
+                    client.logger.warning(
+                        f"Instance is connected but client has not received connected event yet. Last {len(connected_trace.call_record)} traces:")
+
+                    for record in connected_trace.get_call_record():
+                        client.logger.warning(
+                            f"[{record.called_at}] Called connected with args {record.args} retval {record.retval}",
+                            exc_info=record.stack)
 
             await self.wait(self.lifetime_check_interval)
 
@@ -91,6 +107,10 @@ async def stop_lifetime(self, client: Client) -> None:
 
         lifetime.stop()
 
+    async def restart_lifetime(self, client: Client) -> None:
+        await self.stop_lifetime(client)
+        await self.start_lifetime(client)
+
     def remove(self, client: Client) -> None:
         lifetime = self.lifetimes.pop(client, None)
 

simplyprint_ws_client/connection/connection.py

@@ -13,6 +13,7 @@
 from ..events.client_events import ClientEvent, ClientEventMode
 from ..events.event import Event
 from ..events.event_bus import EventBus
+from ..utils.traceability import traceable
 
 
 class ConnectionPollEvent(Event):
@@ -167,6 +168,7 @@ async def send_event(self, client: Client, event: ClientEvent) -> None:
             self.logger.error(f"Failed to send event {event}", exc_info=e)
             await self.on_disconnect()
 
+    @traceable
     async def poll_event(self, timeout=None) -> None:
         if not self.is_connected():
             self.logger.debug(f"Did not poll event because not connected")

simplyprint_ws_client/helpers/file_backup.py

@@ -42,3 +42,24 @@ def backup_file(file: Path, max_count: int = 5, max_age: Optional[datetime.timed
 
         # Now create the new backup by copying the original file
         shutil.copy(file, file.parent / f"{file.name}.bak.0")
+
+    @staticmethod
+    def strip_log_file(file: Path, max_size: int = 100 * 1024 * 1024):
+        """Strip a log file to a maximum size"""
+
+        if not file.exists():
+            return
+
+        if file.stat().st_size <= max_size:
+            return
+
+        # Use the size to start seeking from the end of the file
+        # and then read the file in chunks of 1024 bytes until we have read the last size
+        # then overwrite the file with the new content
+        with open(file, "r+") as f:
+            f.seek(0, 2)
+            f.seek(f.tell() - max_size, 0)
+            content = f.read()
+            f.seek(0)
+            f.write(content)
+            f.truncate()