Merge pull request #42 from PeteRager/0.1.9-dev

Message logger fix for multiple connections, sibling data processing

.gitignore

@@ -9,5 +9,6 @@ eggs
 parts
 log.txt.log
 *.egg-info
+*.tmp
 lib
 lib64

lennoxs30api/__init__.py

@@ -1,4 +1,4 @@
-__version__ = "0.1.8"
+__version__ = "0.1.9"
 from .lennox_home import *
 from .lennox_period import *
 from .lennox_schedule import *

lennoxs30api/message_logger.py

@@ -10,16 +10,18 @@ def __init__(
         self, logger=None, enabled: bool = True, message_logging_file: str = None
     ):
         if message_logging_file != None:
-            self.logger = logging.getLogger(__name__)
+            self.loggerName = __name__ + "." + message_logging_file
+            self.logger = logging.getLogger(self.loggerName)
             self.logger.setLevel(level=logging.DEBUG)
             logFormatter = logging.Formatter(
                 "%(asctime)s [%(threadName)-12.12s] [%(levelname)-5.5s]  %(message)s"
             )
-
-            fileHandler = logging.FileHandler(message_logging_file)
-            fileHandler.setFormatter(logFormatter)
-            fileHandler.setLevel(logging.DEBUG)
-            self.logger.addHandler(fileHandler)
+            ## If the logger already exists and has a handler to write to the file then do not add another one.
+            if len(self.logger.handlers) == 0:
+                fileHandler = logging.FileHandler(message_logging_file)
+                fileHandler.setFormatter(logFormatter)
+                fileHandler.setLevel(logging.DEBUG)
+                self.logger.addHandler(fileHandler)
             # When running in this mode, message should only appear in the message log and not also the default log.
             self.logger.propagate = False
         else:

lennoxs30api/metrics.py

@@ -27,6 +27,9 @@ def reset(self) -> None:
         self.last_reconnect_time: datetime = None
         self.last_message_time: datetime = None
 
+        self.sibling_message_drop: int = 0
+        self.sender_message_drop: int = 0
+
         self.bytes_in: int = 0
         self.bytes_out: int = 0
 
@@ -45,13 +48,15 @@ def getMetricList(self):
             "http_4xx_cnt": self.http_4xx_cnt,
             "http_5xx_cnt": self.http_5xx_cnt,
             "timeouts": self.timeouts,
-            "client_respone_errors": self.client_response_errors,
+            "client_response_errors": self.client_response_errors,
             "server_disconnects": self.server_disconnects,
             "connection_errors": self.connection_errors,
             "last_receive_time": self.last_receive_time,
             "last_error_time": self.last_error_time,
             "last_reconnect_time": self.last_reconnect_time,
             "last_message_time": self.last_message_time,
+            "sender_message_drop": self.sender_message_drop,
+            "sibling_message_drop": self.sibling_message_drop,
         }
 
     def inc_message_count(self) -> None:
@@ -92,6 +97,12 @@ def inc_client_response_errors(self) -> None:
         self.client_response_errors += 1
         self.last_error_time = self.now()
 
+    def inc_sibling_message_drop(self) -> None:
+        self.sibling_message_drop += 1
+
+    def inc_sender_message_drop(self) -> None:
+        self.sender_message_drop += 1
+
     def process_http_code(self, http_code: int) -> None:
         if http_code >= 200 and http_code <= 299:
             self.http_2xx_cnt += 1

lennoxs30api/s30api_async.py

@@ -685,7 +685,20 @@ def processMessage(self, message):
         if system != None:
             system.processMessage(message)
         else:
-            _LOGGER.error("messagePump unknown SenderId/SystemId [" + str(sysId) + "]")
+            system: lennox_system = self.getSystemSibling(sysId)
+            if system == None:
+                self.metrics.inc_sender_message_drop()
+                _LOGGER.error(f"processMessage unknown SenderId/SystemId [{sysId}]")
+            else:
+                self.metrics.inc_sibling_message_drop()
+                if self.metrics.sibling_message_drop == 1:
+                    _LOGGER.warning(
+                        f"processMessage dropping message from sibling [{sysId}] for system [{system.sysId}] - please consult https://github.com/PeteRager/lennoxs30/blob/master/docs/sibling.md for configuration assistance"
+                    )
+                else:
+                    _LOGGER.debug(
+                        f"processMessage dropping message from sibling [{sysId}] for system [{system.sysId}]"
+                    )
 
     # Messages seem to use unique GUIDS, here we create one
     def getNewMessageID(self):
@@ -758,6 +771,12 @@ def getSystem(self, sysId) -> "lennox_system":
                 return system
         return None
 
+    def getSystemSibling(self, sysId: str) -> "lennox_system":
+        for system in self._systemList:
+            if system.sibling_identifier == sysId:
+                return system
+        return None
+
     def getOrCreateSystem(self, sysId: str) -> "lennox_system":
         system = self.getSystem(sysId)
         if system != None:
@@ -979,6 +998,13 @@ def __init__(self, sysId: str):
         self.sa_cancel: bool = None
         self.sa_state: str = None
         self.sa_setpointState: str = None
+        # Sibling data
+        self.sibling_self_identifier: str = None
+        self.sibling_identifier: str = None
+        self.sibling_systemName: str = None
+        self.sibling_nodePresent: str = None
+        self.sibling_portNumber: str = None
+        self.sibling_ipAddress: str = None
 
         self._dirty = False
         self._dirtyList = []
@@ -990,6 +1016,7 @@ def __init__(self, sysId: str):
             "devices": self._processDevices,
             "equipments": self._processEquipments,
             "systemControl": self._processSystemControl,
+            "siblings": self._processSiblings,
         }
         _LOGGER.info(f"Creating lennox_system sysId [{self.sysId}]")
 
@@ -1052,6 +1079,24 @@ def _processSystemControl(self, systemControl):
         if "diagControl" in systemControl:
             self.attr_updater(systemControl["diagControl"], "level", "diagLevel")
 
+    def _processSiblings(self, siblings):
+        i = len(siblings)
+        if i == 0:
+            return
+        if i > 1:
+            _LOGGER.error(
+                f"Encountered system with more than one sibling, please open an issue.  Message: {siblings}"
+            )
+        # It appears there could be more than one of these, for now lets only process the first one.
+        sibling = siblings[0]
+        self.attr_updater(sibling, "selfIdentifier", "sibling_self_identifier")
+        if "sibling" in sibling:
+            self.attr_updater(sibling["sibling"], "identifier", "sibling_identifier")
+            self.attr_updater(sibling["sibling"], "systemName", "sibling_systemName")
+            self.attr_updater(sibling["sibling"], "portNumber", "sibling_portNumber")
+            self.attr_updater(sibling["sibling"], "nodePresent", "sibling_nodePresent")
+            self.attr_updater(sibling["sibling"], "ipAddress", "sibling_ipAddress")
+
     def _processSchedules(self, schedules):
         """Processes the schedule messages, throws base exceptions if a problem is encoutered"""
         for schedule in schedules:

setup.py

@@ -5,7 +5,7 @@
 
 setuptools.setup(
     name="lennoxs30api",
-    version="0.1.8",
+    version="0.1.9",
     description="API Wrapper for Lennox S30 Cloud and LAN API",
     long_description=long_description,
     long_description_content_type="text/markdown",

simulator/main.py

@@ -21,6 +21,7 @@ def __init__(self, configfile: str):
         self.appList = {}
         self.zoneSimRunning = False
         self.outdoorTempSimRunning = False
+        self.siblingSimRunning = False
         with open(configfile) as f:
             self.config_data = json.load(f)
 
@@ -105,6 +106,67 @@ async def zoneSimulator(self):
                 humidity = humidity + 1
             await asyncio.sleep(5.0)
 
+    async def siblingSimulator(self):
+        if self.siblingSimRunning == True:
+            return
+        self.siblingSimRunning = True
+        message = {
+            "MessageId": 0,
+            "SenderID": "LCC",
+            "TargetID": "homeassistant",
+            "MessageType": "PropertyChange",
+            "Data": {
+                "siblings": [
+                    {
+                        "publisher": {"publisherName": "lcc"},
+                        "id": 0,
+                        "selfIdentifier": "KL21J00001",
+                        "sibling": {
+                            "identifier": "KL21J00002",
+                            "systemName": '"Bedrooms"',
+                            "nodePresent": True,
+                            "portNumber": 443,
+                            "groupCountTracker": True,
+                            "ipAddress": "10.0.0.2",
+                        },
+                    }
+                ]
+            },
+        }
+        for appName, appObject in self.appList.items():
+            appObject.queue.append(message)
+        await asyncio.sleep(15.0)
+
+        temperature = 100
+        while True:
+            if temperature == 100:
+                status = LENNOX_STATUS_NOT_AVAILABLE
+            else:
+                status = LENNOX_STATUS_GOOD
+            message = {
+                "MessageId": "637594500464320381|95a6cacebd94459dbe7538161628bdb6",
+                "SenderId": "KL21J00002",
+                "TargetID": "mapp079372367644467046827098_myemail@email.com",
+                "MessageType": "PropertyChange",
+                "Data": {
+                    "system": {
+                        "status": {
+                            "outdoorTemperatureStatus": status,
+                            "outdoorTemperature": temperature,
+                            "outdoorTemperatureC": 13.5,
+                        },
+                        "publisher": {"publisherName": "lcc"},
+                    }
+                },
+            }
+            for appName, appObject in self.appList.items():
+                appObject.queue.append(message)
+            if temperature == 200:
+                temperature = 100
+            else:
+                temperature = temperature + 10
+            await asyncio.sleep(5.0)
+
     def loadfile(self, name) -> json:
         script_dir = os.path.dirname(__file__)
         file_path = os.path.join(script_dir, "../" + name)
@@ -142,6 +204,7 @@ async def request_data(self, request: Request):
                 app.queue.append(data)
                 asyncio.create_task(self.outdoorTempSimulator())
                 asyncio.create_task(self.zoneSimulator())
+                asyncio.create_task(self.siblingSimulator())
                 return web.Response(text="Simulator Success")
         return web.Response(status=404, text="Simulator Failuer")
 

tests/messages/sibling.json

@@ -0,0 +1,25 @@
+{
+    "MessageId": 0,
+    "SenderID": "0000000-0000-0000-0000-000000000002",
+    "TargetID": "homeassistant",
+    "MessageType": "PropertyChange",
+    "Data": {
+        "siblings": [
+            {
+                "publisher": {
+                    "publisherName": "lcc"
+                },
+                "id": 0,
+                "selfIdentifier": "KL21J00001",
+                "sibling": {
+                    "identifier": "KL21J00002",
+                    "systemName": "\"Bedrooms\"",
+                    "nodePresent": true,
+                    "portNumber": 443,
+                    "groupCountTracker": true,
+                    "ipAddress": "10.0.0.2"
+                }
+            }
+        ]
+    }
+}

tests/messages/sibling_multiple.json

@@ -0,0 +1,42 @@
+{
+    "_comment" : "This is not a real messages that was captured, it's purpose is to test error handling",
+    "MessageId": 0,
+    "SenderID": "0000000-0000-0000-0000-000000000002",
+    "TargetID": "homeassistant",
+    "MessageType": "PropertyChange",
+    "Data": {
+        "siblings": [
+            {
+                "publisher": {
+                    "publisherName": "lcc"
+                },
+                "id": 0,
+                "selfIdentifier": "KL21J00001",
+                "sibling": {
+                    "identifier": "KL21J00002",
+                    "systemName": "\"Bedrooms\"",
+                    "nodePresent": true,
+                    "portNumber": 443,
+                    "groupCountTracker": true,
+                    "ipAddress": "10.0.0.2"
+                }
+            },
+            {
+                "publisher": {
+                    "publisherName": "lcc"
+                },
+                "id": 0,
+                "selfIdentifier": "KL21J00003",
+                "sibling": {
+                    "identifier": "KL21J00004",
+                    "systemName": "\"Living Room\"",
+                    "nodePresent": true,
+                    "portNumber": 443,
+                    "groupCountTracker": true,
+                    "ipAddress": "10.0.0.3"
+                }
+            }
+
+        ]
+    }
+}

tests/messages/sibling_zero.json

@@ -0,0 +1,11 @@
+{
+    "_comment" : "This is not a real messages that was captured, it's purpose is to test error handling",
+    "MessageId": 0,
+    "SenderID": "0000000-0000-0000-0000-000000000002",
+    "TargetID": "homeassistant",
+    "MessageType": "PropertyChange",
+    "Data": {
+        "siblings": [
+        ]
+    }
+}

tests/test_api_process_message.py

@@ -0,0 +1,53 @@
+import logging
+from lennoxs30api.s30api_async import (
+    lennox_system,
+    s30api_async,
+)
+
+from tests.conftest import loadfile
+
+
+def test_api_process_sibling_message(api: s30api_async, caplog):
+    lsystem: lennox_system = api.getSystems()[1]
+    assert lsystem.sysId == "0000000-0000-0000-0000-000000000002"
+
+    message = loadfile("sibling.json")
+    api.processMessage(message)
+
+    assert lsystem.sibling_self_identifier == "KL21J00001"
+    assert lsystem.sibling_identifier == "KL21J00002"
+    assert api.metrics.sibling_message_drop == 0
+    message = loadfile("mut_sys1_zone1_status.json")
+    message["SenderId"] = "KL21J00002"
+    caplog.clear()
+    api.metrics.reset()
+    with caplog.at_level(logging.DEBUG):
+        api.processMessage(message)
+        assert len(caplog.records) == 1
+        assert "KL21J00002" in caplog.messages[0]
+        assert caplog.records[0].levelname == "WARNING"
+        assert api.metrics.sibling_message_drop == 1
+        assert api.metrics.sender_message_drop == 0
+
+        api.processMessage(message)
+        assert len(caplog.records) == 2
+        assert "KL21J00002" in caplog.messages[1]
+        assert caplog.records[1].levelname == "DEBUG"
+        assert api.metrics.sibling_message_drop == 2
+        assert api.metrics.sender_message_drop == 0
+
+
+def test_api_process_unknown_sender(api: s30api_async, caplog):
+    lsystem: lennox_system = api.getSystems()[1]
+    assert lsystem.sysId == "0000000-0000-0000-0000-000000000002"
+    message = loadfile("mut_sys1_zone1_status.json")
+    message["SenderId"] = "KL21J00002"
+    caplog.clear()
+    api.metrics.reset()
+    with caplog.at_level(logging.DEBUG):
+        api.processMessage(message)
+        assert len(caplog.records) == 1
+        assert "KL21J00002" in caplog.messages[0]
+        assert caplog.records[0].levelname == "ERROR"
+        assert api.metrics.sibling_message_drop == 0
+        assert api.metrics.sender_message_drop == 1