diff --git a/e3dc/_e3dc.py b/e3dc/_e3dc.py index 8aac428..5a2189a 100644 --- a/e3dc/_e3dc.py +++ b/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() diff --git a/e3dc/_e3dc_rscp_web.py b/e3dc/_e3dc_rscp_web.py index fc4e54d..68f9c4c 100644 --- a/e3dc/_e3dc_rscp_web.py +++ b/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): diff --git a/e3dc/_rscpLib.py b/e3dc/_rscpLib.py index 29501a3..fa9b598 100644 --- a/e3dc/_rscpLib.py +++ b/e3dc/_rscpLib.py @@ -4,6 +4,7 @@ # Copyright 2017 Francesco Santini # 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 = '' 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 = "