Fix web connection broken by E3DC server protocol update

e3dc/_e3dc.py

@@ -5,6 +5,7 @@
 # Licensed under a MIT license. See LICENSE for details
 import datetime
 import hashlib
+import logging
 import struct
 import time
 import uuid
@@ -21,6 +22,8 @@
 from ._rscpLib import rscpFindTag, rscpFindTagIndex
 from ._rscpTags import RscpTag, RscpType, getStrPowermeterType, getStrPviType
 
+logger = logging.getLogger(__name__)
+
 REMOTE_ADDRESS = "https://s10.e3dc.com/s10/phpcmd/cmd.php"
 REQUEST_INTERVAL_SEC = 10  # minimum interval between requests
 REQUEST_INTERVAL_SEC_LOCAL = 1  # minimum interval between requests
@@ -238,6 +241,7 @@ def sendRequest(
                 retry += 1
                 if retry > retries:
                     raise SendError("Max retries reached")
+                logger.warning("Request failed, retrying (%d/%d)", retry, retries, exc_info=True)
 
         if not keepAlive:
             self.rscp.disconnect()

e3dc/_e3dc_rscp_web.py

@@ -5,6 +5,7 @@
 # Licensed under a MIT license. See LICENSE for details
 import datetime
 import hashlib
+import logging
 import struct
 import threading
 import time
@@ -24,6 +25,8 @@
 )
 from ._rscpTags import RscpTag, RscpType, getRscpTag
 
+logger = logging.getLogger(__name__)
+
 """
  The connection works the following way: (> outgoing, < incoming)
 
@@ -121,7 +124,7 @@ def __init__(
             REMOTE_ADDRESS,
             on_message=lambda _, msg: self.on_message(msg),
             on_close=lambda _ws, _, __: self.reset(),
-            on_error=lambda _ws, _: self.reset(),
+            on_error=lambda _ws, err: (logger.warning("WebSocket error: %s", err) or self.reset())
         )
         self.reset()
 
@@ -139,6 +142,7 @@ def reset(self):
 
     def buildVirtualConn(self):
         """Method to create Virtual Connection."""
+        logger.debug("Requesting virtual connection for %s", self.serialNumberWithPrefix)
         virtualConn = rscpFrame(
             rscpEncode(
                 RscpTag.SERVER_REQ_NEW_VIRTUAL_CONNECTION,
@@ -230,9 +234,15 @@ def registerConnectionHandler(self, decodedMsg: RscpMessage):
         if self.conId == 0:
             self.conId = rscpFindTagIndex(decodedMsg, RscpTag.SERVER_CONNECTION_ID)
             self.authLevel = rscpFindTagIndex(decodedMsg, RscpTag.SERVER_AUTH_LEVEL)
+            logger.debug("Initial connection registered: conId=%s authLevel=%s", self.conId, self.authLevel)
         else:
             self.virtConId = rscpFindTagIndex(decodedMsg, RscpTag.SERVER_CONNECTION_ID)
             self.virtAuthLevel = rscpFindTagIndex(decodedMsg, RscpTag.SERVER_AUTH_LEVEL)
+            if self.virtConId == -1:
+                logger.error("Authentication failed: server rejected credentials")
+                self.virtConId = None
+            else:
+                logger.debug("Virtual connection registered: virtConId=%s virtAuthLevel=%s", self.virtConId, self.virtAuthLevel)
         # reply = rscpFrame(rscpEncode(RscpTag.SERVER_CONNECTION_REGISTERED, RscpType.Container, [decodedMsg[2][0], decodedMsg[2][1]]));
         reply = rscpFrame(
             rscpEncode(
@@ -260,7 +270,12 @@ def on_message(self, message: bytes):
             raise
 
         # print "Decoded received message", decodedMsg
-        if tag == RscpTag.SERVER_REQ_PING:
+        if tag == RscpTag.RSCP_REQ_SET_PROTOCOL_VERSION:
+            logger.debug("Protocol version request: v%s, acknowledging", decodedMsg[2])
+            reply = rscpFrame(rscpEncode(RscpTag.RSCP_SET_PROTOCOL_VERSION, decodedMsg[1], decodedMsg[2]))
+            self.ws.send(reply, ABNF.OPCODE_BINARY)
+            return
+        elif tag == RscpTag.SERVER_REQ_PING:
             pingFrame = rscpFrame(
                 rscpEncode(RscpTag.SERVER_PING, RscpType.NoneType, None)
             )
@@ -272,8 +287,7 @@ def on_message(self, message: bytes):
         elif tag == RscpTag.SERVER_REGISTER_CONNECTION:
             self.registerConnectionHandler(decodedMsg)
         elif tag == RscpTag.SERVER_UNREGISTER_CONNECTION:
-            # this signifies some error
-            self.disconnect()
+            logger.warning("Server unregistered connection")
         elif tag == RscpTag.SERVER_REQ_RSCP_CMD:
             data = rscpFrameDecode(
                 rscpFindTagIndex(decodedMsg, RscpTag.SERVER_RSCP_DATA)
@@ -330,6 +344,7 @@ def sendRequest(self, message: RscpMessage) -> RscpMessage:
                 break
             time.sleep(0.1)
         if not self.responseCallbackCalled:
+            logger.warning("Request timed out after %s seconds", self.TIMEOUT)
             raise RequestTimeoutError
 
         return self.requestResult
@@ -398,6 +413,7 @@ def connect(self):
                 break
             time.sleep(0.1)
         if not self.isConnected():
+            logger.warning("Connection timed out after %s seconds", self.TIMEOUT)
             raise RequestTimeoutError
 
     def disconnect(self):

e3dc/_rscpLib.py

@@ -4,6 +4,7 @@
 # Copyright 2017 Francesco Santini <francesco.santini@gmail.com>
 # Licensed under a MIT license. See LICENSE for details
 
+import logging
 import math
 import struct
 import time
@@ -24,6 +25,8 @@
 # Type alias for RSCP messages
 RscpMessage: TypeAlias = tuple[str | int | RscpTag, str | int | RscpType, Any]
 
+logger = logging.getLogger(__name__)
+
 DEBUG_DICT = {"print_rscp": False}
 
 
@@ -37,6 +40,7 @@ def set_debug(debug: bool):
         Nothing
     """
     DEBUG_DICT["print_rscp"] = debug
+    logger.setLevel(logging.DEBUG if debug else logging.WARNING)
 
 
 packFmtDict_FixedSize = {
@@ -144,8 +148,8 @@ def rscpEncode(
     rscptypeHex = getHexRscpType(rscptype)
     rscptype = getRscpType(rscptype)
 
-    if DEBUG_DICT["print_rscp"]:
-        print(">", tag, rscptype, data)
+    loggable_data = '<redacted>' if tag in (RscpTag.SERVER_PASSWD, RscpTag.SERVER_USER ) else data
+    logger.debug("> %s %s %s", tag, rscptype, loggable_data)
 
     if isinstance(data, str):
         data = data.encode("utf-8")
@@ -207,27 +211,43 @@ def rscpFrame(data: bytes) -> bytes:
 
 def rscpFrameDecode(frameData: bytes, returnFrameLen: bool = False):
     """Decodes RSCP Frame."""
-    headerFmt = "<HHIIIH"
     crcFmt = "I"
     crc = None
 
-    magic, ctrl, sec1, _, ns, length = struct.unpack(
-        headerFmt, frameData[: struct.calcsize(headerFmt)]
-    )
+    # Peek at ctrl to determine frame format
+    _, ctrl_raw = struct.unpack("<HH", frameData[:4])
+    ctrl_peek = endianSwapUint16(ctrl_raw)
+
+    if ctrl_peek & 0x02:
+        # Compact format (protocol v2): no timestamp, 32-bit length
+        # Header: magic(2) + ctrl(2) + length(4) = 8 bytes
+        headerFmt = "<HHI"
+        magic, ctrl, length = struct.unpack(headerFmt, frameData[: struct.calcsize(headerFmt)])
+        magic = endianSwapUint16(magic)
+        ctrl = endianSwapUint16(ctrl)
+        timestamp = 0.0
+    else:
+        # Standard format: magic(2) + ctrl(2) + sec1(4) + sec2(4) + ns(4) + length(2) = 18 bytes
+        headerFmt = "<HHIIIH"
+        magic, ctrl, sec1, _, ns, length = struct.unpack(
+            headerFmt, frameData[: struct.calcsize(headerFmt)]
+        )
+        magic = endianSwapUint16(magic)
+        ctrl = endianSwapUint16(ctrl)
+        timestamp = sec1 + float(ns) / 1000
 
-    magic = endianSwapUint16(magic)
-    ctrl = endianSwapUint16(ctrl)
+    headerSize = struct.calcsize(headerFmt)
 
     if ctrl & 0x10:  # crc enabled
-        totalLen = struct.calcsize(headerFmt) + length + struct.calcsize(crcFmt)
+        totalLen = headerSize + length + struct.calcsize(crcFmt)
         data, crc = struct.unpack(
             "<" + str(length) + "s" + crcFmt,
-            frameData[struct.calcsize(headerFmt) : totalLen],
+            frameData[headerSize : totalLen],
         )
     else:
-        totalLen = struct.calcsize(headerFmt) + length
+        totalLen = headerSize + length
         data = struct.unpack(
-            "<" + str(length) + "s", frameData[struct.calcsize(headerFmt) : totalLen]
+            "<" + str(length) + "s", frameData[headerSize : totalLen]
         )[0]
 
     # check crc
@@ -238,7 +258,6 @@ def rscpFrameDecode(frameData: bytes, returnFrameLen: bool = False):
         if crcCalc != crc:
             raise FrameError("CRC32 not validated")
 
-    timestamp = sec1 + float(ns) / 1000
     if returnFrameLen:
         return data, timestamp, totalLen
     else:
@@ -305,7 +324,6 @@ def rscpDecode(
         # ignore none utf-8 bytes
         val = val.decode("utf-8", "ignore")
 
-    if DEBUG_DICT["print_rscp"]:
-        print("<", strTag, strType, val)
+    logger.debug("< %s %s %s", strTag, strType, val)
 
-    return (strTag, strType, val), headerSize + struct.calcsize(fmt)
+    return (strTag, strType, val), headerSize + length