Small fixes to make the Elegoo connection more reliable.

Author: QuinnDamerell

elegoo_octoeverywhere/elegooclient.py

@@ -7,6 +7,7 @@
 from typing import Any, Dict, List, Optional
 
 from octoeverywhere.compat import Compat
+from octoeverywhere.repeattimer import RepeatTimer
 from octoeverywhere.sentry import Sentry
 from octoeverywhere.websocketimpl import Client
 from octoeverywhere.octohttprequest import OctoHttpRequest
@@ -184,7 +185,7 @@ def IsDisconnectDueToTooManyClients(self) -> bool:
 
     # Sends a command to the printer to enable the webcam.
     def SendEnableWebcamCommand(self, waitForResponse:bool=True) -> ResponseMsg:
-        return ElegooClient.Get().SendRequest(386, {"Enable":1}, waitForResponse=waitForResponse)
+        return self.SendRequest(386, {"Enable":1}, waitForResponse=waitForResponse)
 
 
     # Sends a command to all connected frontends to show a popup message.
@@ -205,6 +206,8 @@ def SendFrontendPopupMsg(self, title:str, text:str, msgType:str, actionText:Opti
 
     # Sends a request to the printer and waits for a response.
     # Always returns a ResponseMsg, with various error codes.
+    # Full protocol:
+    # https://github.com/cbd-tech/SDCP-Smart-Device-Control-Protocol-V3.0.0/blob/main/SDCP(Smart%20Device%20Control%20Protocol)_V3.0.0_EN.md
     def SendRequest(self, cmdId:int, data:Optional[Dict[str, Any]]=None, waitForResponse:bool=True, timeoutSec:Optional[float]=None) -> ResponseMsg:
         # Generate a request id, which is a 32 char lowercase letter and number string
         requestId = ''.join(random.choices(string.ascii_lowercase + string.digits, k=32))
@@ -330,11 +333,15 @@ def _ClientWorker(self):
                 self.WebSocket = Client(url, onWsOpen=self._OnWsConnect, onWsClose=self._OnWsClose, onWsError=self._OnWsError, onWsData=self._OnWsData)
                 self.WebSocket.SetDisableCertCheck(True)
 
-                # Connect to the server
-                with self.WebSocket:
-                    # Use a more aggressive ping timeout because if the printer power cycles, we don't get the TCP close message.
-                    # Time ping timeout must be less than the ping interval.
-                    self.WebSocket.RunUntilClosed(pingIntervalSec=30)
+                # Important! The connection to the print will close after 1 minute if we don't send any messages.
+                # Even if the websocket sends the ws ping message, it doesn't seem to reset the idle timer.
+                # So, we will use a repeat timer to send the SDCP protocol ping message every 50 seconds.
+                with RepeatTimer(self.Logger, "ElegooClientWsMsgKeepalive", 50.0, self._RepeatTimerKeepaliveTick) as t:
+                    t.start()
+                    # Connect to the server
+                    with self.WebSocket:
+                        # We use a ping payload of "ping" because it's what the web portal uses.
+                        self.WebSocket.RunUntilClosed(pingPayload="ping")
             except Exception as e:
                 Sentry.OnException("Elegoo client exception in main WS loop.", e)
 
@@ -357,6 +364,16 @@ def _ClientWorker(self):
             self.SleepEvent.clear()
 
 
+    def _RepeatTimerKeepaliveTick(self):
+        # Any message works, but this is the lightest weight.
+        # We don't care about the result
+        if self._WebSocketSend(Buffer("ping".encode("utf-8"))) is False:
+            localWs = self.WebSocket
+            if localWs is not None and self.WebSocketConnected is True:
+                self.Logger.info("Elegoo client - keepalive tick failed to send ping message, closing the websocket.")
+                localWs.Close()
+
+
     # Fired whenever the client is disconnected, we need to clean up the state since it's now unknown.
     def _CleanupStateOnDisconnect(self):
         self.State = None
@@ -368,7 +385,7 @@ def _CleanupStateOnDisconnect(self):
 
     # Fired when the websocket is connected.
     def _OnWsConnect(self, ws:IWebSocketClient):
-        self.Logger.info("Connection to the Elegoo printer established!")
+        self.Logger.debug("Elegoo websocket established")
         LocalWebApi.Get().SetPrinterConnectionState(True)
 
         # Set the connected flag now, so we can send messages.
@@ -519,7 +536,7 @@ def _HandleAttributesUpdate(self, attributes:Dict[str, Any]):
                 s = PrinterAttributes(self.Logger)
                 s.OnUpdate(attributes)
                 self.Attributes = s
-                self.Logger.info("Elegoo printer attributes object created.")
+                self.Logger.debug("Elegoo printer attributes object created.")
             else:
                 self.Attributes.OnUpdate(attributes)
         except Exception as e:
@@ -573,7 +590,7 @@ def _HandleAttributesUpdate(self, attributes:Dict[str, Any]):
 
         # We have a match, so we are good.
         self.Config.SetStr(Config.SectionCompanion, Config.CompanionKeyIpOrHostname, wsConIp)
-        self.Logger.info("Elegoo client connection finalized.")
+        self.Logger.info("Elegoo client connection fully connected.")
 
 
     def _HandleStatusUpdate(self, status:Dict[str, Any]):
@@ -585,7 +602,7 @@ def _HandleStatusUpdate(self, status:Dict[str, Any]):
                 s = PrinterState(self.Logger)
                 s.OnUpdate(status)
                 self.State = s
-                self.Logger.info("Elegoo printer state object created.")
+                self.Logger.debug("Elegoo printer state object created.")
             else:
                 self.State.OnUpdate(status)
         except Exception as e:

elegoo_octoeverywhere/slipstream.py

@@ -209,7 +209,7 @@ def _GetAndProcessIndex(self):
         with self.Lock:
             size = len(self.Cache)
 
-        self.Logger.info("Slipstream took "+str(time.time()-start)+f" to fully update the cache of {size} files.")
+        self.Logger.debug("Slipstream took "+str(time.time()-start)+f" to fully update the cache of {size} files.")
 
 
     # On success returns the fully ready OctoHttpResult object.

linux_host/logger.py

@@ -4,6 +4,8 @@
 import logging.handlers
 from typing import Optional
 
+from octoeverywhere.websocketimpl import Client
+
 from .config import Config
 
 class LoggerInit:
@@ -39,6 +41,9 @@ def GetLogger(config:Config, logDir:str, logLevelOverride:Optional[str]) -> logg
         # Set the final log level.
         logger.setLevel(logLevel)
 
+        # Set the websocket lib debug level if needed.
+        Client.SetWebsocketDebuggingLevel(logLevel == "DEBUG")
+
         # Define our format
         formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
 

moonraker_octoeverywhere/moonrakerclient.py

@@ -770,12 +770,12 @@ def _onWsClose(self, ws:IWebSocketClient) -> None:
     def _onWsError(self, ws:IWebSocketClient, exception:Exception) -> None:
         if Sentry.IsCommonConnectionException(exception):
             # Don't bother logging, this just means there's no server to connect to.
-            pass
-        elif isinstance(exception, octowebsocket.WebSocketBadStatusException) and "Handshake status" in str(exception):
+            return
+        if isinstance(exception, octowebsocket.WebSocketBadStatusException) and "Handshake status" in str(exception):
             # This is moonraker specific, we sometimes see stuff like "Handshake status 502 Bad Gateway"
             self.Logger.info(f"Failed to connect to moonraker due to bad gateway stats. {exception}")
-        else:
-            Sentry.OnException("Exception rased from moonraker client websocket connection. The connection will be closed.", exception)
+            return
+        Sentry.OnException("Exception raised from moonraker client websocket connection. The connection will be closed.", exception)
 
 
 # A helper class used for waiting rpc requests

octoeverywhere/notificationshandler.py

@@ -236,7 +236,7 @@ def OnRestorePrintIfNeeded(self, isPrinting:bool, isPaused:bool, printCookie_Can
                 self.StopTimers()
                 return
             else:
-                self.Logger.info("Restore client sync state: There's no print and none of the timers are running.")
+                self.Logger.debug("Restore client sync state: There's no print and none of the timers are running.")
                 return
 
 

octoeverywhere/repeattimer.py

@@ -26,7 +26,7 @@ def run(self):
                 self.callback()
             except Exception as e:
                 Sentry.OnException("Exception in RepeatTimer thread.", e)
-        self.logger.info("RepeatTimer thread exit")
+        self.logger.debug("RepeatTimer thread exit")
 
 
     # Used to update the repeat interval. This can be called while the timer is running

octoeverywhere/sentry.py

@@ -330,13 +330,18 @@ def _HandleCantCreateThreadException(logger:logging.Logger, e:Exception) -> bool
     @staticmethod
     def IsCommonConnectionException(e:Exception) -> bool:
         def matchesException(exception:Exception, exceptionClass:Any, msgs:Optional[List[str]]=None) -> bool:
+            # First, ensure that the exception matches the one we are filtering for.
             if not isinstance(exception, exceptionClass):
                 return False
+            # If no messages are provided, then any exception of this type matches.
+            if msgs is None:
+                return True
+            # Check the exception string for any of the provided messages.
             exceptionStr = str(exception).lower().strip()
-            if msgs is not None:
-                for t in msgs:
-                    if t.lower() in exceptionStr:
-                        return True
+            for t in msgs:
+                if t.lower() in exceptionStr:
+                    return True
+            # If no messages matched, then we matched the exception type, but not the message, so return false.
             return False
 
         try:
@@ -366,6 +371,9 @@ def matchesException(exception:Exception, exceptionClass:Any, msgs:Optional[List
             # We don't care.
             if matchesException(e, octowebsocket.WebSocketConnectionClosedException):
                 return True
+            # If the ping pong tim
+            if matchesException(e, octowebsocket.WebSocketTimeoutException, ["ping/pong timed out"]):
+                return True
         except Exception:
             pass
         return False

octoeverywhere/websocketimpl.py

@@ -1,6 +1,7 @@
 import queue
 import ssl
 import threading
+import logging
 from typing import Any, Dict, List, Callable, Optional
 
 import certifi
@@ -15,6 +16,20 @@
 # This class gives a bit of an abstraction over the normal ws
 class Client(IWebSocketClient):
 
+
+    # Allows us to still enable the websocket debug logs if we want.
+    @staticmethod
+    def SetWebsocketDebuggingLevel(debug:bool) -> None:
+        # The websocket lib logs quite a lot of stuff, even to info. It will also always logs errors,
+        # even after our handler had handled them. So we will disable it by default.
+        wsLibLogger = logging.getLogger("websocket")
+        if debug is False:
+            wsLibLogger.disabled = True
+            return
+        wsLibLogger.disabled = False
+        wsLibLogger.setLevel(logging.DEBUG)
+
+
     def __init__(
                 self,
                 url:str,
@@ -47,9 +62,6 @@ def __init__(
         self.SendQueue:queue.Queue[SendQueueContext] = queue.Queue()
         self.SendThread:threading.Thread = None #pyright: ignore[reportAttributeAccessIssue]
 
-        # Used to log more details about what's going on with the websocket.
-        # websocket.enableTrace(True)
-
         # Used to indicate if the client has started to close this WS. If so, we won't fire
         # any errors.
         self.hasClientRequestedClose = False
@@ -105,7 +117,7 @@ def SetDisableCertCheck(self, disable:bool):
 
 
     # Runs the websocket blocking until it closes.
-    def RunUntilClosed(self, pingIntervalSec:Optional[int]=None, pingTimeoutSec:Optional[int]=None):
+    def RunUntilClosed(self, pingIntervalSec:Optional[int]=None, pingTimeoutSec:Optional[int]=None, pingPayload:str="") -> None:
         #
         # The client is responsible for sending keep alive pings the server will then pong respond to.
         # If that's not done, the connection will timeout. We will send a ping every 10 minutes.
@@ -151,7 +163,7 @@ def RunUntilClosed(self, pingIntervalSec:Optional[int]=None, pingTimeoutSec:Opti
                 if self.isClosed:
                     return
 
-            self.Ws.run_forever(skip_utf8_validation=True, ping_interval=pingIntervalSec, ping_timeout=pingTimeoutSec, sslopt=sslopt)  #pyright: ignore[reportUnknownMemberType]
+            self.Ws.run_forever(skip_utf8_validation=True, ping_interval=pingIntervalSec, ping_timeout=pingTimeoutSec, sslopt=sslopt, ping_payload=pingPayload)  #pyright: ignore[reportUnknownMemberType]
         except Exception as e:
             # There's a compat issue where  run_forever will try to access "isAlive" when the socket is closing
             # "isAlive" apparently doesn't exist in some PY versions of thread, so this throws. We will ignore that error,