From f3fc384f159b02fdb1fcc327acec9ffb3d066758 Mon Sep 17 00:00:00 2001 From: Elad Bar Date: Sun, 23 Jun 2024 13:52:20 +0300 Subject: [PATCH 1/4] handle timeouts as managed failure instead of general failure --- CHANGELOG.md | 2 ++ custom_components/mydolphin_plus/managers/rest_api.py | 4 +++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 95f0f24..200fbb0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,8 @@ - Remove startup blocking call - Improve reconnect process (cool-down between attempts) +- Handle timeouts as managed failure instead of general failure +- Ignore update request when the connection is not established ## v1.0.14 diff --git a/custom_components/mydolphin_plus/managers/rest_api.py b/custom_components/mydolphin_plus/managers/rest_api.py index b453a1e..a84a1d3 100644 --- a/custom_components/mydolphin_plus/managers/rest_api.py +++ b/custom_components/mydolphin_plus/managers/rest_api.py @@ -188,6 +188,9 @@ async def _async_post(self, url, headers: dict, request_data: str | dict | None) elif crex.status in [404, 405]: self._set_status(ConnectivityStatus.NotFound) + except TimeoutError: + _LOGGER.error(f"Failed to post JSON to {url} due to timeout") + except Exception as ex: exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno @@ -398,7 +401,6 @@ async def _generate_token(self): async def _load_details(self): if self._status != ConnectivityStatus.Connected: - self._set_status(ConnectivityStatus.Failed) return try: From f3df5c563f4c69bb04cec6dfe3cf49b9ef92febc Mon Sep 17 00:00:00 2001 From: Elad Bar <3207137+elad-bar@users.noreply.github.com> Date: Sun, 23 Jun 2024 13:59:11 +0300 Subject: [PATCH 2/4] handle timeouts as managed failure instead of general failure (#206) --- CHANGELOG.md | 2 ++ custom_components/mydolphin_plus/managers/rest_api.py | 4 +++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 95f0f24..200fbb0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,8 @@ - Remove startup blocking call - Improve reconnect process (cool-down between attempts) +- Handle timeouts as managed failure instead of general failure +- Ignore update request when the connection is not established ## v1.0.14 diff --git a/custom_components/mydolphin_plus/managers/rest_api.py b/custom_components/mydolphin_plus/managers/rest_api.py index b453a1e..a84a1d3 100644 --- a/custom_components/mydolphin_plus/managers/rest_api.py +++ b/custom_components/mydolphin_plus/managers/rest_api.py @@ -188,6 +188,9 @@ async def _async_post(self, url, headers: dict, request_data: str | dict | None) elif crex.status in [404, 405]: self._set_status(ConnectivityStatus.NotFound) + except TimeoutError: + _LOGGER.error(f"Failed to post JSON to {url} due to timeout") + except Exception as ex: exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno @@ -398,7 +401,6 @@ async def _generate_token(self): async def _load_details(self): if self._status != ConnectivityStatus.Connected: - self._set_status(ConnectivityStatus.Failed) return try: From ee01117361afa12b1d376fe3c23bf657cb446846 Mon Sep 17 00:00:00 2001 From: Elad Bar Date: Mon, 24 Jun 2024 09:31:38 +0300 Subject: [PATCH 3/4] improved log messages of status changes --- CHANGELOG.md | 1 + .../mydolphin_plus/managers/aws_client.py | 72 ++++---- .../mydolphin_plus/managers/rest_api.py | 170 ++++++++++-------- 3 files changed, 141 insertions(+), 102 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 200fbb0..d1d492a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Improve reconnect process (cool-down between attempts) - Handle timeouts as managed failure instead of general failure - Ignore update request when the connection is not established +- Improved log messages of status changes ## v1.0.14 diff --git a/custom_components/mydolphin_plus/managers/aws_client.py b/custom_components/mydolphin_plus/managers/aws_client.py index 377be48..e32322c 100644 --- a/custom_components/mydolphin_plus/managers/aws_client.py +++ b/custom_components/mydolphin_plus/managers/aws_client.py @@ -180,14 +180,13 @@ def _on_terminate_future_completed(future): self._awsiot_client = None - self._set_status(ConnectivityStatus.Disconnected) - _LOGGER.debug("AWS Client is disconnected") + self._set_status(ConnectivityStatus.Disconnected, "terminate requested") async def initialize(self): try: - _LOGGER.info("Initializing MyDolphin AWS IOT WS") - - self._set_status(ConnectivityStatus.Connecting) + self._set_status( + ConnectivityStatus.Connecting, "Initializing MyDolphin AWS IOT WS" + ) aws_token = self._api_data.get(API_RESPONSE_DATA_TOKEN) aws_key = self._api_data.get(API_RESPONSE_DATA_ACCESS_KEY_ID) @@ -246,11 +245,9 @@ def _on_connect_future_completed(future): exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno - _LOGGER.error( - f"Failed to initialize MyDolphin Plus WS, error: {ex}, line: {line_number}" - ) + message = f"Failed to initialize MyDolphin Plus WS, error: {ex}, line: {line_number}" - self._set_status(ConnectivityStatus.Failed) + self._set_status(ConnectivityStatus.Failed, message) def _subscribe(self): _LOGGER.debug(f"Subscribing topics: {self._topic_data.subscribe}") @@ -333,23 +330,26 @@ def _on_connection_failure(self, connection, callback_data): if connection is not None and isinstance( callback_data, mqtt.OnConnectionFailureData ): - _LOGGER.error(f"AWS IoT connection failed, Error: {callback_data.error}") + message = f"AWS IoT connection failed, Error: {callback_data.error}" - self._set_status(ConnectivityStatus.Failed) + self._set_status(ConnectivityStatus.Failed, message) def _on_connection_closed(self, connection, callback_data): if connection is not None and isinstance( callback_data, mqtt.OnConnectionClosedData ): - _LOGGER.debug("AWS IoT connection was closed") + message = "AWS IoT connection was closed" - self._set_status(ConnectivityStatus.Disconnected) + self._set_status(ConnectivityStatus.Disconnected, message) def _on_connection_interrupted(self, connection, error, **_kwargs): - _LOGGER.error(f"AWS IoT connection interrupted, Error: {error}") + message = f"AWS IoT connection interrupted, Error: {error}" - if connection is not None: - self._set_status(ConnectivityStatus.Failed) + if connection is None: + _LOGGER.error(message) + + else: + self._set_status(ConnectivityStatus.Failed, message) def _on_connection_resumed( self, connection, return_code, session_present, **_kwargs @@ -641,27 +641,39 @@ def _get_led_settings(self, key, value): return data - def _set_status(self, status: ConnectivityStatus): + def _set_status(self, status: ConnectivityStatus, message: str | None = None): + log_level = ConnectivityStatus.get_log_level(status) + if status != self._status: ignored_transitions = IGNORED_TRANSITIONS.get(self._status, []) + should_perform_action = status not in ignored_transitions - if status in ignored_transitions: - return + log_message = f"Status update {self._status} --> {status}" - log_level = ConnectivityStatus.get_log_level(status) + if not should_perform_action: + log_message = f"{log_message}, no action will be performed" - _LOGGER.log( - log_level, - f"Status changed from '{self._status}' to '{status}'", - ) + if message is None: + log_message = f"{log_message}, {message}" - self._status = status + _LOGGER.log(log_level, log_message) - self._async_dispatcher_send( - SIGNAL_AWS_CLIENT_STATUS, - self._config_manager.entry_id, - status, - ) + if should_perform_action: + self._status = status + + self._async_dispatcher_send( + SIGNAL_AWS_CLIENT_STATUS, + self._config_manager.entry_id, + status, + ) + + else: + log_message = f"Status is {status}" + + if message is None: + log_message = f"{log_message}, {message}" + + _LOGGER.log(log_level, log_message) def set_local_async_dispatcher_send(self, callback): self._local_async_dispatcher_send = callback diff --git a/custom_components/mydolphin_plus/managers/rest_api.py b/custom_components/mydolphin_plus/managers/rest_api.py index a84a1d3..6509748 100644 --- a/custom_components/mydolphin_plus/managers/rest_api.py +++ b/custom_components/mydolphin_plus/managers/rest_api.py @@ -8,6 +8,7 @@ from typing import Any from aiohttp import ClientResponseError, ClientSession +from aiohttp.hdrs import METH_GET, METH_POST from cryptography.hazmat.backends import default_backend from cryptography.hazmat.primitives.ciphers import Cipher, algorithms, modes @@ -136,7 +137,7 @@ async def terminate(self): if self._session is not None: await self._session.close() - self._set_status(ConnectivityStatus.Disconnected) + self._set_status(ConnectivityStatus.Disconnected, "terminate requested") async def _initialize_session(self): try: @@ -150,11 +151,11 @@ async def _initialize_session(self): exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno - _LOGGER.warning( + message = ( f"Failed to initialize session, Error: {str(ex)}, Line: {line_number}" ) - self._set_status(ConnectivityStatus.Failed) + self._set_status(ConnectivityStatus.Failed, message) async def validate(self): await self._initialize_session() @@ -178,28 +179,13 @@ async def _async_post(self, url, headers: dict, request_data: str | dict | None) ) except ClientResponseError as crex: - _LOGGER.error( - f"Failed to post JSON to {url}, HTTP Status: {crex.message} ({crex.status})" - ) - - if crex.status in [401, 403]: - self._set_status(ConnectivityStatus.Failed) - - elif crex.status in [404, 405]: - self._set_status(ConnectivityStatus.NotFound) + self._handle_client_error(url, METH_POST, crex) except TimeoutError: - _LOGGER.error(f"Failed to post JSON to {url} due to timeout") + self._handle_server_timeout(url, METH_POST) except Exception as ex: - exc_type, exc_obj, tb = sys.exc_info() - line_number = tb.tb_lineno - - _LOGGER.error( - f"Failed to post JSON to {url}, Error: {ex}, Line: {line_number}" - ) - - self._set_status(ConnectivityStatus.Failed) + self._handle_general_request_failure(url, METH_POST, ex) return result @@ -219,22 +205,13 @@ async def _async_get(self, url, headers: dict): ) except ClientResponseError as crex: - _LOGGER.error( - f"Failed to get data from {url}, HTTP Status: {crex.message} ({crex.status})" - ) + self._handle_client_error(url, METH_GET, crex) - if crex.status in [404, 405]: - self._set_status(ConnectivityStatus.NotFound) + except TimeoutError: + self._handle_server_timeout(url, METH_GET) except Exception as ex: - exc_type, exc_obj, tb = sys.exc_info() - line_number = tb.tb_lineno - - _LOGGER.error( - f"Failed to get data from {url}, Error: {ex}, Line: {line_number}" - ) - - self._set_status(ConnectivityStatus.Failed) + self._handle_general_request_failure(url, METH_GET, ex) return result @@ -262,7 +239,7 @@ async def _login(self): return else: - self._set_status(ConnectivityStatus.Failed) + self._set_status(ConnectivityStatus.Failed, "general failure of login") async def _service_login(self): try: @@ -276,31 +253,35 @@ async def _service_login(self): payload = await self._async_post(LOGIN_URL, LOGIN_HEADERS, request_data) if payload is None: - payload = {} + self._set_status(ConnectivityStatus.Failed, "empty response of login") - data = payload.get(API_RESPONSE_DATA, {}) - if data: - _LOGGER.info(f"Logged in to user {username}") + else: + data = payload.get(API_RESPONSE_DATA) - motor_unit_serial = data.get(API_REQUEST_SERIAL_NUMBER) - token = data.get(API_REQUEST_HEADER_TOKEN) + if data is None: + self._set_status( + ConnectivityStatus.InvalidCredentials, + "empty response payload of login", + ) - self.data[API_DATA_SERIAL_NUMBER] = motor_unit_serial - self.data[API_DATA_LOGIN_TOKEN] = token + else: + _LOGGER.info(f"Logged in to user {username}") - await self._set_actual_motor_unit_serial() + motor_unit_serial = data.get(API_REQUEST_SERIAL_NUMBER) + token = data.get(API_REQUEST_HEADER_TOKEN) - else: - self._set_status(ConnectivityStatus.InvalidCredentials) + self.data[API_DATA_SERIAL_NUMBER] = motor_unit_serial + self.data[API_DATA_LOGIN_TOKEN] = token + + await self._set_actual_motor_unit_serial() except Exception as ex: exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno - _LOGGER.error( - f"Failed to login into {DEFAULT_NAME} service, Error: {str(ex)}, Line: {line_number}" - ) - self._set_status(ConnectivityStatus.Failed) + message = f"Failed to login into {DEFAULT_NAME} service, Error: {str(ex)}, Line: {line_number}" + + self._set_status(ConnectivityStatus.Failed, message) async def _set_actual_motor_unit_serial(self): try: @@ -323,24 +304,21 @@ async def _set_actual_motor_unit_serial(self): data: dict = payload.get(API_RESPONSE_DATA, {}) if data is not None: - _LOGGER.info( - f"Successfully retrieved details for device {serial_serial}" - ) + message = f"Successfully retrieved details for device {serial_serial}" self.data[API_DATA_MOTOR_UNIT_SERIAL] = data.get( API_RESPONSE_UNIT_SERIAL_NUMBER ) - self._set_status(ConnectivityStatus.TemporaryConnected) + self._set_status(ConnectivityStatus.TemporaryConnected, message) except Exception as ex: exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno - _LOGGER.error( - f"Failed to login into {DEFAULT_NAME} service, Error: {str(ex)}, Line: {line_number}" - ) - self._set_status(ConnectivityStatus.Failed) + message = f"Failed to login into {DEFAULT_NAME} service, Error: {str(ex)}, Line: {line_number}" + + self._set_status(ConnectivityStatus.Failed, message) async def _generate_token(self): try: @@ -382,11 +360,9 @@ async def _generate_token(self): self.data[STORAGE_DATA_AWS_TOKEN_ENCRYPTED_KEY] = None if get_token_attempts + 1 >= MAXIMUM_ATTEMPTS_GET_AWS_TOKEN: - _LOGGER.error( - f"Failed to retrieve AWS token after {get_token_attempts} attempts, Error: {alert}" - ) + message = f"Failed to retrieve AWS token after {get_token_attempts} attempts, Error: {alert}" - self._set_status(ConnectivityStatus.Failed) + self._set_status(ConnectivityStatus.Failed, message) get_token_attempts += 1 @@ -394,10 +370,9 @@ async def _generate_token(self): exc_type, exc_obj, tb = sys.exc_info() line_number = tb.tb_lineno - _LOGGER.error( - f"Failed to retrieve AWS token from service, Error: {str(ex)}, Line: {line_number}" - ) - self._set_status(ConnectivityStatus.Failed) + message = f"Failed to retrieve AWS token from service, Error: {str(ex)}, Line: {line_number}" + + self._set_status(ConnectivityStatus.Failed, message) async def _load_details(self): if self._status != ConnectivityStatus.Connected: @@ -484,14 +459,16 @@ def _get_aes_key(self): return encryption_key - def _set_status(self, status: ConnectivityStatus): + def _set_status(self, status: ConnectivityStatus, message: str | None = None): + log_level = ConnectivityStatus.get_log_level(status) + if status != self._status: - log_level = ConnectivityStatus.get_log_level(status) + log_message = f"Status update {self._status} --> {status}" - _LOGGER.log( - log_level, - f"Status changed from '{self._status}' to '{status}'", - ) + if message is None: + log_message = f"{log_message}, {message}" + + _LOGGER.log(log_level, log_message) self._status = status @@ -499,6 +476,55 @@ def _set_status(self, status: ConnectivityStatus): SIGNAL_API_STATUS, self._config_manager.entry_id, status ) + else: + log_message = f"Status is {status}" + + if message is None: + log_message = f"{log_message}, {message}" + + _LOGGER.log(log_level, log_message) + + def _handle_client_error( + self, endpoint: str, method: str, crex: ClientResponseError + ): + message = ( + "Failed to send HTTP request, " + f"Endpoint: {endpoint}, " + f"Method: {method}, " + f"HTTP Status: {crex.message} ({crex.status})" + ) + + if crex.status in [404, 405]: + self._set_status(ConnectivityStatus.NotFound, message) + + else: + self._set_status(ConnectivityStatus.Failed, message) + + def _handle_server_timeout(self, endpoint: str, method: str): + message = ( + "Failed to send HTTP request due to timeout, " + f"Endpoint: {endpoint}, " + f"Method: {method}" + ) + + self._set_status(ConnectivityStatus.Failed, message) + + def _handle_general_request_failure( + self, endpoint: str, method: str, ex: Exception + ): + exc_type, exc_obj, tb = sys.exc_info() + line_number = tb.tb_lineno + + message = ( + "Failed to send HTTP request, " + f"Endpoint: {endpoint}, " + f"Method: {method}, " + f"Error: {ex}, " + f"Line: {line_number}" + ) + + self._set_status(ConnectivityStatus.Failed, message) + def set_local_async_dispatcher_send(self, callback): self._local_async_dispatcher_send = callback From 3f1d792667db82305adc371a018fa9992c714796 Mon Sep 17 00:00:00 2001 From: Elad Bar Date: Mon, 24 Jun 2024 10:06:33 +0300 Subject: [PATCH 4/4] fix if statement for logging --- custom_components/mydolphin_plus/managers/aws_client.py | 2 +- custom_components/mydolphin_plus/managers/rest_api.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/custom_components/mydolphin_plus/managers/aws_client.py b/custom_components/mydolphin_plus/managers/aws_client.py index e32322c..8e881e5 100644 --- a/custom_components/mydolphin_plus/managers/aws_client.py +++ b/custom_components/mydolphin_plus/managers/aws_client.py @@ -653,7 +653,7 @@ def _set_status(self, status: ConnectivityStatus, message: str | None = None): if not should_perform_action: log_message = f"{log_message}, no action will be performed" - if message is None: + if message is not None: log_message = f"{log_message}, {message}" _LOGGER.log(log_level, log_message) diff --git a/custom_components/mydolphin_plus/managers/rest_api.py b/custom_components/mydolphin_plus/managers/rest_api.py index 6509748..95abf6c 100644 --- a/custom_components/mydolphin_plus/managers/rest_api.py +++ b/custom_components/mydolphin_plus/managers/rest_api.py @@ -465,7 +465,7 @@ def _set_status(self, status: ConnectivityStatus, message: str | None = None): if status != self._status: log_message = f"Status update {self._status} --> {status}" - if message is None: + if message is not None: log_message = f"{log_message}, {message}" _LOGGER.log(log_level, log_message)