From 254dd935c493c38cad65b1359378b85a8d952ecf Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 19 May 2022 11:55:44 -0400 Subject: [PATCH 1/6] Message logger fix for multiple connections, sibling data processing --- .gitignore | 1 + lennoxs30api/message_logger.py | 14 ++--- lennoxs30api/metrics.py | 9 ++++ lennoxs30api/s30api_async.py | 42 ++++++++++++++- tests/messages/sibling.json | 25 +++++++++ tests/messages/sibling_multiple.json | 42 +++++++++++++++ tests/messages/sibling_zero.json | 11 ++++ tests/test_api_process_message.py | 46 ++++++++++++++++ tests/test_message_logger.py | 14 +++++ tests/test_siblings.py | 81 ++++++++++++++++++++++++++++ 10 files changed, 278 insertions(+), 7 deletions(-) create mode 100644 tests/messages/sibling.json create mode 100644 tests/messages/sibling_multiple.json create mode 100644 tests/messages/sibling_zero.json create mode 100644 tests/test_api_process_message.py create mode 100644 tests/test_siblings.py diff --git a/.gitignore b/.gitignore index 0a34beb..85209a7 100644 --- a/.gitignore +++ b/.gitignore @@ -9,5 +9,6 @@ eggs parts log.txt.log *.egg-info +*.tmp lib lib64 \ No newline at end of file diff --git a/lennoxs30api/message_logger.py b/lennoxs30api/message_logger.py index 57f2666..5826edf 100644 --- a/lennoxs30api/message_logger.py +++ b/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: diff --git a/lennoxs30api/metrics.py b/lennoxs30api/metrics.py index be67e6a..3c66534 100644 --- a/lennoxs30api/metrics.py +++ b/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 @@ -92,6 +95,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 diff --git a/lennoxs30api/s30api_async.py b/lennoxs30api/s30api_async.py index 97423f2..d0f484f 100644 --- a/lennoxs30api/s30api_async.py +++ b/lennoxs30api/s30api_async.py @@ -685,7 +685,15 @@ 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() + _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 +766,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 +993,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 +1011,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 +1074,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: diff --git a/tests/messages/sibling.json b/tests/messages/sibling.json new file mode 100644 index 0000000..e228d2e --- /dev/null +++ b/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" + } + } + ] + } +} diff --git a/tests/messages/sibling_multiple.json b/tests/messages/sibling_multiple.json new file mode 100644 index 0000000..0e74830 --- /dev/null +++ b/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" + } + } + + ] + } +} diff --git a/tests/messages/sibling_zero.json b/tests/messages/sibling_zero.json new file mode 100644 index 0000000..70f0017 --- /dev/null +++ b/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": [ + ] + } +} diff --git a/tests/test_api_process_message.py b/tests/test_api_process_message.py new file mode 100644 index 0000000..8a8d9b1 --- /dev/null +++ b/tests/test_api_process_message.py @@ -0,0 +1,46 @@ +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 == "DEBUG" + assert api.metrics.sibling_message_drop == 1 + 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 diff --git a/tests/test_message_logger.py b/tests/test_message_logger.py index 616aa5e..e23e022 100644 --- a/tests/test_message_logger.py +++ b/tests/test_message_logger.py @@ -115,3 +115,17 @@ def test_logging_redacted_performance(caplog): ) print(t1) pass + + +def test_logger_instances_separate(caplog): + # Message Loggers are unique per file. So when specifying different files we should get different loggers + mlog1 = MessageLogger(enabled=True, message_logging_file="s30_log_file_1.tmp") + mlog2 = MessageLogger(enabled=True, message_logging_file="s30_log_file_2.tmp") + assert mlog1.logger != mlog2.logger + + # Message Loggers are unique per file. So when specifying different files we should get the same logger + mlog1 = MessageLogger(enabled=True, message_logging_file="s30_log_file_1.tmp") + mlog2 = MessageLogger(enabled=True, message_logging_file="s30_log_file_1.tmp") + assert mlog1.logger == mlog2.logger + # There should only be one handler for the loggers. + assert len(mlog1.logger.handlers) == 1 diff --git a/tests/test_siblings.py b/tests/test_siblings.py new file mode 100644 index 0000000..6aae019 --- /dev/null +++ b/tests/test_siblings.py @@ -0,0 +1,81 @@ +import logging +from lennoxs30api.s30api_async import ( + lennox_system, + s30api_async, +) + +from tests.conftest import loadfile + + +def test_process_sibling_message(api: s30api_async): + lsystem: lennox_system = api.getSystems()[1] + assert lsystem.sysId == "0000000-0000-0000-0000-000000000002" + + assert lsystem.sibling_self_identifier == None + assert lsystem.sibling_identifier == None + assert lsystem.sibling_systemName == None + assert lsystem.sibling_nodePresent == None + assert lsystem.sibling_portNumber == None + assert lsystem.sibling_ipAddress == None + + message = loadfile("sibling.json") + api.processMessage(message) + + assert lsystem.sibling_self_identifier == "KL21J00001" + assert lsystem.sibling_identifier == "KL21J00002" + assert lsystem.sibling_systemName == '"Bedrooms"' + assert lsystem.sibling_nodePresent == True + assert lsystem.sibling_portNumber == 443 + assert lsystem.sibling_ipAddress == "10.0.0.2" + + +def test_process_multiple_sibling_message(api: s30api_async, caplog): + lsystem: lennox_system = api.getSystems()[1] + assert lsystem.sysId == "0000000-0000-0000-0000-000000000002" + + assert lsystem.sibling_self_identifier == None + assert lsystem.sibling_identifier == None + assert lsystem.sibling_systemName == None + assert lsystem.sibling_nodePresent == None + assert lsystem.sibling_portNumber == None + assert lsystem.sibling_ipAddress == None + + # Testing the error reporting if we encouter multiple siblings + message = loadfile("sibling_multiple.json") + caplog.clear() + with caplog.at_level(logging.ERROR): + api.processMessage(message) + # The first record should process + assert lsystem.sibling_self_identifier == "KL21J00001" + assert lsystem.sibling_identifier == "KL21J00002" + assert lsystem.sibling_systemName == '"Bedrooms"' + assert lsystem.sibling_nodePresent == True + assert lsystem.sibling_portNumber == 443 + assert lsystem.sibling_ipAddress == "10.0.0.2" + assert len(caplog.records) == 1 + assert "KL21J00003" in caplog.messages[0] + assert "KL21J00004" in caplog.messages[0] + + +def test_process_zero_sibling_message(api: s30api_async, caplog): + lsystem: lennox_system = api.getSystems()[1] + assert lsystem.sysId == "0000000-0000-0000-0000-000000000002" + + assert lsystem.sibling_self_identifier == None + assert lsystem.sibling_identifier == None + assert lsystem.sibling_systemName == None + assert lsystem.sibling_nodePresent == None + assert lsystem.sibling_portNumber == None + assert lsystem.sibling_ipAddress == None + + message = loadfile("sibling_zero.json") + caplog.clear() + with caplog.at_level(logging.ERROR): + api.processMessage(message) + assert lsystem.sibling_self_identifier == None + assert lsystem.sibling_identifier == None + assert lsystem.sibling_systemName == None + assert lsystem.sibling_nodePresent == None + assert lsystem.sibling_portNumber == None + assert lsystem.sibling_ipAddress == None + assert len(caplog.records) == 0 From becc42c06f59fd2542f20837b24e6c3074092538 Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 19 May 2022 12:01:15 -0400 Subject: [PATCH 2/6] Add new metrics to list --- lennoxs30api/metrics.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lennoxs30api/metrics.py b/lennoxs30api/metrics.py index 3c66534..6b6fc4b 100644 --- a/lennoxs30api/metrics.py +++ b/lennoxs30api/metrics.py @@ -48,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: From e959738e0c304d9a3d13d404a302490b16014cf5 Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 19 May 2022 17:45:43 -0400 Subject: [PATCH 3/6] Update simulator to generate sibling data --- simulator/main.py | 63 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 63 insertions(+) diff --git a/simulator/main.py b/simulator/main.py index 23e5f2f..21c90fb 100644 --- a/simulator/main.py +++ b/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") From d86506174df87a2815e6d850668b838aa94d47dd Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 19 May 2022 17:46:53 -0400 Subject: [PATCH 4/6] Bump version to 0.1.9 --- lennoxs30api/__init__.py | 2 +- setup.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lennoxs30api/__init__.py b/lennoxs30api/__init__.py index 753ae0f..7d95fe7 100644 --- a/lennoxs30api/__init__.py +++ b/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 * diff --git a/setup.py b/setup.py index 66da08d..fafe05a 100644 --- a/setup.py +++ b/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", From 50c5f8df80ad764f033cec50e0847007ae0f2f19 Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 19 May 2022 17:58:34 -0400 Subject: [PATCH 5/6] Add embedded spaces to test --- tests/test_message_logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_message_logger.py b/tests/test_message_logger.py index e23e022..674171a 100644 --- a/tests/test_message_logger.py +++ b/tests/test_message_logger.py @@ -124,8 +124,8 @@ def test_logger_instances_separate(caplog): assert mlog1.logger != mlog2.logger # Message Loggers are unique per file. So when specifying different files we should get the same logger - mlog1 = MessageLogger(enabled=True, message_logging_file="s30_log_file_1.tmp") - mlog2 = MessageLogger(enabled=True, message_logging_file="s30_log_file_1.tmp") + mlog1 = MessageLogger(enabled=True, message_logging_file="s30_log file_1.tmp") + mlog2 = MessageLogger(enabled=True, message_logging_file="s30_log file_1.tmp") assert mlog1.logger == mlog2.logger # There should only be one handler for the loggers. assert len(mlog1.logger.handlers) == 1 From a43d0464d2c0441219dfe3cd0101aa99c437890f Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Sun, 22 May 2022 17:01:21 -0400 Subject: [PATCH 6/6] Log warning on first sibling message --- lennoxs30api/s30api_async.py | 11 ++++++++--- tests/test_api_process_message.py | 9 ++++++++- 2 files changed, 16 insertions(+), 4 deletions(-) diff --git a/lennoxs30api/s30api_async.py b/lennoxs30api/s30api_async.py index d0f484f..1f205d6 100644 --- a/lennoxs30api/s30api_async.py +++ b/lennoxs30api/s30api_async.py @@ -691,9 +691,14 @@ def processMessage(self, message): _LOGGER.error(f"processMessage unknown SenderId/SystemId [{sysId}]") else: self.metrics.inc_sibling_message_drop() - _LOGGER.debug( - f"processMessage dropping message from sibling [{sysId}] for system [{system.sysId}]" - ) + 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): diff --git a/tests/test_api_process_message.py b/tests/test_api_process_message.py index 8a8d9b1..a9aaefe 100644 --- a/tests/test_api_process_message.py +++ b/tests/test_api_process_message.py @@ -25,10 +25,17 @@ def test_api_process_sibling_message(api: s30api_async, caplog): api.processMessage(message) assert len(caplog.records) == 1 assert "KL21J00002" in caplog.messages[0] - assert caplog.records[0].levelname == "DEBUG" + 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]