diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 163d7c4..5be785f 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -41,7 +41,7 @@ repos: rev: 6.0.1 hooks: - id: isort - args: ["--profile", "black"] + args: ["--profile", "black", "-o", "aiohttp", "-o", "apyhiveapi", "-o", "boto3", "-o", "botocore", "-o", "pyquery", "-o", "requests", "-o", "setuptools", "-o", "six", "-o", "urllib3"] - repo: https://github.com/adrienverge/yamllint.git rev: v1.37.1 hooks: diff --git a/setup.cfg b/setup.cfg index aa9ef6f..596c9a0 100644 --- a/setup.cfg +++ b/setup.cfg @@ -34,13 +34,9 @@ build-backend = "setuptools.build_meta" [bdist_wheel] universal = 1 -[settings] -multi_line_output = 3 -include_trailing_comma = True -known_third_party = aiohttp,boto3,botocore,pyquery,requests,setuptools,six,urllib3 - [tool.isort] profile = "black" +known_third_party = aiohttp,apyhiveapi,boto3,botocore,pyquery,requests,setuptools,six,urllib3 [flake8] diff --git a/setup.py b/setup.py index 56e8373..c072c78 100644 --- a/setup.py +++ b/setup.py @@ -17,7 +17,7 @@ def requirements_from_file(filename="requirements.txt"): setup( - version="1.0.8", + version="1.0.9", packages=["apyhiveapi", "apyhiveapi.api", "apyhiveapi.helper"], package_dir={"apyhiveapi": "src"}, package_data={"data": ["*.json"]}, diff --git a/src/api/hive_api.py b/src/api/hive_api.py index a2f0c44..6f21c81 100644 --- a/src/api/hive_api.py +++ b/src/api/hive_api.py @@ -2,6 +2,7 @@ # pylint: skip-file import json +import logging import requests import urllib3 @@ -9,6 +10,8 @@ urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning) +_LOGGER = logging.getLogger(__name__) + class HiveApi: """Hive API Code.""" @@ -43,6 +46,10 @@ def __init__(self, hiveSession=None, websession=None, token=None): def request(self, type, url, jsc=None, camera=False): """Make API request.""" + _LOGGER.debug("request - Making %s request to: %s", type, url) + if jsc: + _LOGGER.debug("request - Request payload: %s", jsc) + if self.session is not None: if camera: self.headers = { @@ -72,17 +79,27 @@ def request(self, type, url, jsc=None, camera=False): "authorization": self.token, } - if type == "GET": - return requests.get( - url=url, headers=self.headers, data=jsc, timeout=self.timeout - ) - if type == "POST": - return requests.post( - url=url, headers=self.headers, data=jsc, timeout=self.timeout - ) + _LOGGER.debug( + "request - Request headers: %s", + {k: v for k, v in self.headers.items() if k.lower() != "authorization"}, + ) + + try: + if type == "GET": + return requests.get( + url=url, headers=self.headers, data=jsc, timeout=self.timeout + ) + if type == "POST": + return requests.post( + url=url, headers=self.headers, data=jsc, timeout=self.timeout + ) + except Exception as e: + _LOGGER.error("Request failed: %s", e) + raise def refreshTokens(self, tokens={}): """Get new session tokens - DEPRECATED NOW BY AWS TOKEN MANAGEMENT.""" + _LOGGER.debug("refreshTokens - Attempting token refresh (deprecated method)") url = self.urls["refresh"] if self.session is not None: tokens = self.session.tokens.tokenData @@ -97,21 +114,31 @@ def refreshTokens(self, tokens={}): info = self.request("POST", url, jsc) data = json.loads(info.text) if "token" in data and self.session: + _LOGGER.debug( + "refreshTokens - Token refresh successful, updating session" + ) self.session.updateTokens(data) self.urls.update({"base": data["platform"]["endpoint"]}) self.urls.update({"camera": data["platform"]["cameraPlatform"]}) self.json_return.update({"original": info.status_code}) self.json_return.update({"parsed": info.json()}) - except (OSError, RuntimeError, ZeroDivisionError): + except (OSError, RuntimeError, ZeroDivisionError, json.JSONDecodeError) as e: + _LOGGER.error("Token refresh failed: %s", str(e)) self.error() return self.json_return def getLoginInfo(self): """Get login properties to make the login request.""" + _LOGGER.debug( + "getLoginInfo - Fetching login info from: %s", self.urls["properties"] + ) url = self.urls["properties"] try: data = requests.get(url=url, verify=False, timeout=self.timeout) + _LOGGER.debug( + "getLoginInfo - Login info response status: %s", data.status_code + ) html = PyQuery(data.content) json_data = json.loads( '{"' @@ -126,19 +153,35 @@ def getLoginInfo(self): loginData.update({"UPID": json_data["HiveSSOPoolId"]}) loginData.update({"CLIID": json_data["HiveSSOPublicCognitoClientId"]}) loginData.update({"REGION": json_data["HiveSSOPoolId"]}) + _LOGGER.debug("getLoginInfo - Login info extracted successfully") return loginData - except (OSError, RuntimeError, ZeroDivisionError): + except ( + OSError, + RuntimeError, + ZeroDivisionError, + json.JSONDecodeError, + KeyError, + ) as e: + _LOGGER.error("Failed to get login info: %s", str(e)) self.error() def getAll(self): """Build and query all endpoint.""" + _LOGGER.debug("getAll - Fetching all devices/products/actions from Hive API") json_return = {} url = self.urls["base"] + self.urls["all"] try: info = self.request("GET", url) - json_return.update({"original": info.status_code}) - json_return.update({"parsed": info.json()}) - except (OSError, RuntimeError, ZeroDivisionError): + if info is not None: + json_return.update({"original": info.status_code}) + json_return.update({"parsed": info.json()}) + _LOGGER.debug( + "getAll - All data fetch successful, status: %s", info.status_code + ) + else: + _LOGGER.error("Failed to get response from all endpoint") + except (OSError, RuntimeError, ZeroDivisionError, json.JSONDecodeError) as e: + _LOGGER.error("Failed to fetch all data: %s", str(e)) self.error() return json_return @@ -259,6 +302,12 @@ def getWeather(self, weather_url): def setState(self, n_type, n_id, **kwargs): """Set the state of a Device.""" + _LOGGER.debug( + "setState - Setting state for device %s (type: %s): %s", + n_id, + n_type, + kwargs, + ) jsc = ( "{" + ",".join( @@ -271,9 +320,24 @@ def setState(self, n_type, n_id, **kwargs): try: response = self.request("POST", url, jsc) - self.json_return.update({"original": response.status_code}) - self.json_return.update({"parsed": response.json()}) - except (OSError, RuntimeError, ZeroDivisionError, ConnectionError): + if response is not None: + self.json_return.update({"original": response.status_code}) + self.json_return.update({"parsed": response.json()}) + _LOGGER.debug( + "setState - State set successfully for %s, status: %s", + n_id, + response.status_code, + ) + else: + _LOGGER.error("Failed to set state for %s - no response", n_id) + except ( + OSError, + RuntimeError, + ZeroDivisionError, + ConnectionError, + json.JSONDecodeError, + ) as e: + _LOGGER.error("Failed to set state for %s: %s", n_id, str(e)) self.error() return self.json_return @@ -293,6 +357,7 @@ def setAction(self, n_id, data): def error(self): """An error has occurred interacting with the Hive API.""" + _LOGGER.error("API error occurred - returning error response") self.json_return.update({"original": "Error making API call"}) self.json_return.update({"parsed": "Error making API call"}) diff --git a/src/api/hive_async_api.py b/src/api/hive_async_api.py index 8a29a2e..9ff9d18 100644 --- a/src/api/hive_async_api.py +++ b/src/api/hive_async_api.py @@ -169,7 +169,6 @@ async def getAll(self): """Build and query all endpoint.""" json_return = {} url = self.urls["all"] - _LOGGER.debug("Fetching all nodes from Hive API.") try: resp = await self.request("get", url) json_return.update({"original": resp.status}) @@ -303,7 +302,7 @@ async def getWeather(self, weather_url): async def setState(self, n_type, n_id, **kwargs): """Set the state of a Device.""" - _LOGGER.debug("Setting state for %s/%s: %s", n_type, n_id, kwargs) + _LOGGER.debug("setState - Setting state for %s/%s: %s", n_type, n_id, kwargs) json_return = {} jsc = ( "{" diff --git a/src/api/hive_auth_async.py b/src/api/hive_auth_async.py index e1532b3..0cd2f25 100644 --- a/src/api/hive_auth_async.py +++ b/src/api/hive_auth_async.py @@ -23,7 +23,6 @@ HiveInvalidDeviceAuthentication, HiveInvalidPassword, HiveInvalidUsername, - HiveReauthRequired, HiveRefreshTokenExpired, ) from .hive_api import HiveApi @@ -183,8 +182,9 @@ def get_password_authentication_key(self, username, password, server_b_value, sa ) return hkdf - async def get_auth_params(self): + async def get_auth_params(self, is_device_login=False): """Get auth params.""" + _LOGGER.debug("get_auth_params - Getting auth params") auth_params = { "USERNAME": self.username, "SRP_A": long_to_hex(self.large_a_value), @@ -197,6 +197,11 @@ async def get_auth_params(self): ) } ) + + if is_device_login: + auth_params["DEVICE_KEY"] = self.device_key + + _LOGGER.debug("Auth params: %s", auth_params) return auth_params @staticmethod @@ -356,17 +361,18 @@ async def process_challenge(self, challenge_parameters): return response async def login(self): - """Login into a Hive account.""" + """Login into a Hive account - handles initial SRP auth only.""" if self.use_file: - _LOGGER.debug("Using file-based authentication.") + _LOGGER.debug("login - Using file-based authentication.") return self.file_response if self.client is None: await self.async_init() + auth_params = await self.get_auth_params() response = None result = None - _LOGGER.debug("Initiating SRP auth with Cognito.") + _LOGGER.debug("login - Initiating SRP auth with Cognito.") try: response = await self.loop.run_in_executor( None, @@ -387,7 +393,7 @@ async def login(self): raise HiveApiError from err if response["ChallengeName"] == self.PASSWORD_VERIFIER_CHALLENGE: - _LOGGER.debug("Processing PASSWORD_VERIFIER challenge.") + _LOGGER.debug("login - Processing PASSWORD_VERIFIER challenge.") challenge_response = await self.process_challenge( response["ChallengeParameters"] ) @@ -417,6 +423,8 @@ async def login(self): ) raise HiveApiError from err + _LOGGER.debug("login - SRP auth challenge completed successfully.") + if ( "AuthenticationResult" in result and "NewDeviceMetadata" in result["AuthenticationResult"] @@ -428,67 +436,58 @@ async def login(self): self.device_key = result["AuthenticationResult"]["NewDeviceMetadata"][ "DeviceKey" ] + _LOGGER.debug("login - Device keys stored successfully.") - _LOGGER.debug("SRP auth challenge completed successfully.") return result + challenge_name = response["ChallengeName"] _LOGGER.error("Unsupported Cognito challenge: %s", challenge_name) raise NotImplementedError(f"The {challenge_name} challenge is not supported") async def device_login(self): - """Perform device login instead.""" - _LOGGER.debug("Starting device SRP authentication.") - login_result = await self.login() + """Perform device login - handles DEVICE_SRP_AUTH challenge. - if "AuthenticationResult" in login_result: - # Login succeeded without a device challenge (e.g. device tracking - # not enforced). Tokens are already valid, return them directly. - return login_result + Returns: + dict: Authentication result with tokens. + """ + _LOGGER.debug("device_login - Starting device SRP authentication.") - auth_params = await self.get_auth_params() - auth_params["DEVICE_KEY"] = self.device_key + if self.client is None: + await self.async_init() - if login_result.get("ChallengeName") == self.DEVICE_VERIFIER_CHALLENGE: - _LOGGER.debug("Processing DEVICE_SRP_AUTH challenge.") - try: - initial_result = await self.loop.run_in_executor( - None, - functools.partial( - self.client.respond_to_auth_challenge, - ClientId=self.__client_id, - ChallengeName=self.DEVICE_VERIFIER_CHALLENGE, - ChallengeResponses=auth_params, - ), - ) + auth_params = await self.get_auth_params(is_device_login=True) - device_challenge_response = await self.process_device_challenge( - initial_result["ChallengeParameters"] - ) - result = await self.loop.run_in_executor( - None, - functools.partial( - self.client.respond_to_auth_challenge, - ClientId=self.__client_id, - ChallengeName=self.DEVICE_PASSWORD_CHALLENGE, - ChallengeResponses=device_challenge_response, - ), - ) - except botocore.exceptions.EndpointConnectionError as err: - if err.__class__.__name__ == "EndpointConnectionError": - _LOGGER.error("Device login failed: cannot reach endpoint.") - raise HiveApiError from err - elif login_result.get("ChallengeName") == self.SMS_MFA_CHALLENGE: - # Account has 2FA enabled and device is not remembered by Cognito. - # Automatic re-authentication is not possible without user interaction. - raise HiveReauthRequired - else: - _LOGGER.error( - "Device login failed: expected DEVICE_SRP_AUTH challenge, got %s.", - login_result.get("ChallengeName"), + _LOGGER.debug("device_login - Processing DEVICE_SRP_AUTH challenge.") + try: + initial_result = await self.loop.run_in_executor( + None, + functools.partial( + self.client.respond_to_auth_challenge, + ClientId=self.__client_id, + ChallengeName=self.DEVICE_VERIFIER_CHALLENGE, + ChallengeResponses=auth_params, + ), + ) + + device_challenge_response = await self.process_device_challenge( + initial_result["ChallengeParameters"] + ) + result = await self.loop.run_in_executor( + None, + functools.partial( + self.client.respond_to_auth_challenge, + ClientId=self.__client_id, + ChallengeName=self.DEVICE_PASSWORD_CHALLENGE, + ChallengeResponses=device_challenge_response, + ), ) - raise HiveInvalidDeviceAuthentication + except botocore.exceptions.EndpointConnectionError as err: + if err.__class__.__name__ == "EndpointConnectionError": + _LOGGER.error("Device login failed: cannot reach endpoint.") + raise HiveApiError from err + raise HiveInvalidDeviceAuthentication from err - _LOGGER.debug("Device authentication completed successfully.") + _LOGGER.debug("device_login - Device authentication completed successfully.") return result async def sms_2fa( @@ -500,7 +499,7 @@ async def sms_2fa( session = challenge_parameters.get("Session") code = str(entered_code) result = None - _LOGGER.debug("Submitting SMS 2FA code to Cognito.") + _LOGGER.debug("sms_2fa - Submitting SMS 2FA code to Cognito.") try: result = await self.loop.run_in_executor( None, @@ -535,12 +534,12 @@ async def sms_2fa( _LOGGER.error("2FA failed: cannot reach Cognito endpoint.") raise HiveApiError from err - _LOGGER.debug("2FA authentication completed successfully.") + _LOGGER.debug("sms_2fa - 2FA authentication completed successfully.") return result async def device_registration(self, device_name: str = None): """Register device with Hive.""" - _LOGGER.debug("Registering device with Hive.") + _LOGGER.debug("device_registration - Registering device with Hive.") await self.confirm_device(device_name) await self.update_device_status() @@ -611,7 +610,7 @@ async def refresh_token(self, token): """Refresh Hive Tokens.""" if self.client is None: await self.async_init() - _LOGGER.debug("Requesting token refresh from Cognito.") + _LOGGER.debug("refresh_token - Requesting token refresh from Cognito.") result = None auth_params = {"REFRESH_TOKEN": token} if self.device_key is not None: @@ -641,16 +640,112 @@ async def refresh_token(self, token): _LOGGER.warning("Refresh token is invalid or expired.") raise HiveRefreshTokenExpired from err - _LOGGER.error("Token refresh failed: %s - %s", error_code, error_message) + _LOGGER.error( + "refresh_token - Token refresh failed: %s - %s", + error_code, + error_message, + ) raise HiveFailedToRefreshTokens from err except botocore.exceptions.EndpointConnectionError as err: if err.__class__.__name__ == "EndpointConnectionError": - _LOGGER.error("Token refresh failed: cannot reach Cognito endpoint.") + _LOGGER.error( + "refresh_token - Token refresh failed: cannot reach Cognito endpoint." + ) raise HiveApiError from err - _LOGGER.debug("Cognito token refresh completed successfully.") + _LOGGER.debug("refresh_token - Cognito token refresh completed successfully.") return result + async def is_device_registered(self, access_token=None, device_key=None): + """Check if the current device is registered with Cognito. + + Args: + access_token (str, optional): Access token. Defaults to self.access_token. + device_key (str, optional): Device key. Defaults to self.device_key. + + Returns: + bool: True if device is registered and remembered, False otherwise. + + Raises: + HiveApiError: If unable to reach Cognito endpoint. + """ + if self.client is None: + await self.async_init() + + token = access_token or self.access_token + key = device_key or self.device_key + + if not token or not key: + _LOGGER.debug( + "is_device_registered - Missing access token or device key, " + "device not registered" + ) + return False + + _LOGGER.debug( + "is_device_registered - Checking device registration status for device: %s", + key, + ) + + try: + result = await self.loop.run_in_executor( + None, + functools.partial( + self.client.get_device, + AccessToken=token, + DeviceKey=key, + ), + ) + + if result and "Device" in result: + device_status = result["Device"].get("DeviceAttributes", []) + # Check if device is in "remembered" status + for attr in device_status: + if ( + attr.get("Name") == "dev:device_remembered_status" + and attr.get("Value") == "remembered" + ): + _LOGGER.debug( + "is_device_registered - Device %s is registered and remembered", + key, + ) + return True + + _LOGGER.debug( + "is_device_registered - Device %s is registered but not remembered", + key, + ) + + except botocore.exceptions.ClientError as err: + error = (err.response or {}).get("Error", {}) + error_code = error.get("Code") + error_message = error.get("Message", "") + + if error_code == "ResourceNotFoundException": + _LOGGER.debug( + "is_device_registered - Device %s not found in Cognito", key + ) + elif error_code == "NotAuthorizedException": + _LOGGER.warning( + "is_device_registered - Not authorized to check device status: %s", + error_message, + ) + else: + _LOGGER.error( + "is_device_registered - Error checking device status: %s - %s", + error_code, + error_message, + ) + + except botocore.exceptions.EndpointConnectionError as err: + _LOGGER.error( + "is_device_registered - Cannot reach Cognito endpoint: %s", str(err) + ) + raise HiveApiError from err + + # Default: device not registered or status unknown + return False + async def forget_device(self, access_token, device_key): """Forget device registered with Hive.""" if self.client is None: diff --git a/src/camera.py b/src/camera.py index 15e2661..4418979 100644 --- a/src/camera.py +++ b/src/camera.py @@ -94,7 +94,7 @@ async def setCameraOn(self, device: dict, mode: str): device["hiveID"] in self.session.data.devices and device["deviceData"]["online"] ): - _LOGGER.debug("Setting camera ON for %s.", device["haName"]) + _LOGGER.debug("setCameraOn - Setting camera ON for %s.", device["haName"]) await self.session.hiveRefreshTokens() resp = await self.session.api.setState(mode=mode) if resp["original"] == 200: @@ -118,7 +118,7 @@ async def setCameraOff(self, device: dict, mode: str): device["hiveID"] in self.session.data.devices and device["deviceData"]["online"] ): - _LOGGER.debug("Setting camera OFF for %s.", device["haName"]) + _LOGGER.debug("setCameraOff - Setting camera OFF for %s.", device["haName"]) await self.session.hiveRefreshTokens() resp = await self.session.api.setState(mode=mode) if resp["original"] == 200: @@ -156,7 +156,7 @@ async def getCamera(self, device: dict): cached = self.session.getCachedDevice(device) if cached is not None: _LOGGER.debug( - "Returning cached state for camera %s (slow/busy poll).", + "getCamera - Returning cached state for camera %s (slow/busy poll).", device["haName"], ) return cached @@ -167,7 +167,7 @@ async def getCamera(self, device: dict): if device["deviceData"]["online"]: self.session.helper.deviceRecovered(device["device_id"]) - _LOGGER.debug("Updating camera data for %s.", device["haName"]) + _LOGGER.debug("getCamera - Updating camera data for %s.", device["haName"]) data = self.session.data.devices[device["device_id"]] dev_data = { "hiveID": device["hiveID"], diff --git a/src/heating.py b/src/heating.py index 3a9cfd2..822ae49 100644 --- a/src/heating.py +++ b/src/heating.py @@ -56,6 +56,7 @@ async def getCurrentTemperature(self, device: dict): state = None final = None + device_name = device.get("haName", device.get("hiveID", "Unknown")) try: data = self.session.data.products[device["hiveID"]] @@ -64,10 +65,10 @@ async def getCurrentTemperature(self, device: dict): try: state = float(state) except (ValueError, TypeError): - _LOGGER.debug( - "Non-numeric temperature value '%s' for %s.", + _LOGGER.warning( + "getCurrentTemperature - Non-numeric temperature value '%s' for %s.", state, - device.get("haName", device.get("hiveID")), + device_name, ) return None @@ -105,7 +106,11 @@ async def getCurrentTemperature(self, device: dict): final = round(state, 1) except KeyError as e: - _LOGGER.error(e) + _LOGGER.error( + "getCurrentTemperature - KeyError getting temperature for %s: %s", + device_name, + str(e), + ) return final @@ -119,6 +124,7 @@ async def getTargetTemperature(self, device: dict): float: Target temperature or None if invalid """ state = None + device_name = device.get("haName", device.get("hiveID", "Unknown")) try: data = self.session.data.products[device["hiveID"]] @@ -130,14 +136,18 @@ async def getTargetTemperature(self, device: dict): try: state = float(state) except (ValueError, TypeError): - _LOGGER.debug( - "Non-numeric target temperature value '%s' for %s.", + _LOGGER.warning( + "getTargetTemperature - Non-numeric target temperature value '%s' for %s.", state, - device.get("haName", device.get("hiveID")), + device_name, ) return None except (KeyError, TypeError) as e: - _LOGGER.error(e) + _LOGGER.error( + "getTargetTemperature - Error getting target temperature for %s: %s", + device_name, + str(e), + ) return state @@ -287,6 +297,13 @@ async def setTargetTemperature(self, device: dict, new_temp: str): Returns: boolean: True/False if successful """ + device_name = device.get("haName", device.get("hiveID", "Unknown")) + _LOGGER.info( + "setTargetTemperature - Setting target temperature to %s°C for %s", + new_temp, + device_name, + ) + await self.session.hiveRefreshTokens() final = False @@ -295,7 +312,8 @@ async def setTargetTemperature(self, device: dict, new_temp: str): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting target temperature to %s for %s.", new_temp, device["haName"] + "setTargetTemperature - Device %s is online, proceeding with temperature change", + device_name, ) data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( @@ -303,8 +321,23 @@ async def setTargetTemperature(self, device: dict, new_temp: str): ) if resp["original"] == 200: + _LOGGER.debug( + "setTargetTemperature - Temperature set successfully for %s, refreshing device data", + device_name, + ) await self.session.getDevices(device["hiveID"]) final = True + else: + _LOGGER.error( + "setTargetTemperature - Failed to set temperature for %s, response: %s", + device_name, + resp["original"], + ) + else: + _LOGGER.warning( + "setTargetTemperature - Device %s not found or offline, cannot set temperature", + device_name, + ) return final @@ -318,6 +351,11 @@ async def setMode(self, device: dict, new_mode: str): Returns: boolean: True/False if successful """ + device_name = device.get("haName", device.get("hiveID", "Unknown")) + _LOGGER.info( + "setMode - Setting heating mode to %s for %s", new_mode, device_name + ) + await self.session.hiveRefreshTokens() final = False @@ -326,7 +364,8 @@ async def setMode(self, device: dict, new_mode: str): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting heating mode to %s for %s.", new_mode, device["haName"] + "setMode - Device %s is online, proceeding with mode change", + device_name, ) data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( @@ -334,8 +373,22 @@ async def setMode(self, device: dict, new_mode: str): ) if resp["original"] == 200: + _LOGGER.debug( + "setMode - Mode set successfully for %s, refreshing device data", + device_name, + ) await self.session.getDevices(device["hiveID"]) final = True + else: + _LOGGER.error( + "setMode - Failed to set mode for %s, response: %s", + device_name, + resp["original"], + ) + else: + _LOGGER.warning( + "setMode - Device %s not found or offline, cannot set mode", device_name + ) return final @@ -360,7 +413,7 @@ async def setBoostOn(self, device: dict, mins: str, temp: float): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting heating boost ON for %s: %s mins at %s degrees.", + "setBoostOn - Setting heating boost ON for %s: %s mins at %s degrees.", device["haName"], mins, temp, @@ -396,7 +449,9 @@ async def setBoostOff(self, device: dict): device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Setting heating boost OFF for %s.", device["haName"]) + _LOGGER.debug( + "setBoostOff - Setting heating boost OFF for %s.", device["haName"] + ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] await self.session.getDevices(device["hiveID"]) @@ -437,7 +492,9 @@ async def setHeatOnDemand(self, device: dict, state: str): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting heat on demand to %s for %s.", state, device["haName"] + "setHeatOnDemand - Setting heat on demand to %s for %s.", + state, + device["haName"], ) data = self.session.data.products[device["hiveID"]] await self.session.hiveRefreshTokens() @@ -480,7 +537,7 @@ async def getClimate(self, device: dict): cached = self.session.getCachedDevice(device) if cached is not None: _LOGGER.debug( - "Returning cached state for climate %s (slow/busy poll).", + "getClimate - Returning cached state for climate %s (slow/busy poll).", device["haName"], ) return cached @@ -491,7 +548,9 @@ async def getClimate(self, device: dict): if device["deviceData"]["online"]: dev_data = {} self.session.helper.deviceRecovered(device["device_id"]) - _LOGGER.debug("Updating climate data for %s.", device["haName"]) + _LOGGER.debug( + "getClimate - Updating climate data for %s.", device["haName"] + ) data = self.session.data.devices[device["device_id"]] dev_data = { "hiveID": device["hiveID"], @@ -518,6 +577,11 @@ async def getClimate(self, device: dict): device["device_id"], device["hiveType"] ), } + _LOGGER.debug( + "getHeating - Heating device data for %s: %s", + device["haName"], + dev_data["status"], + ) return self.session.setCachedDevice(device, dev_data) else: await self.session.helper.errorCheck( diff --git a/src/helper/hive_helper.py b/src/helper/hive_helper.py index 77ab690..8fe8b6e 100644 --- a/src/helper/hive_helper.py +++ b/src/helper/hive_helper.py @@ -1,9 +1,11 @@ """Helper class for pyhiveapi.""" # pylint: skip-file +import copy import datetime import logging import operator +from typing import Any from .const import HIVE_TYPES @@ -21,7 +23,7 @@ def __init__(self, session: object = None): """ self.session = session - def getDeviceName(self, n_id: str): + async def getDeviceName(self, n_id: str): """Resolve a id into a name. Args: @@ -30,24 +32,34 @@ def getDeviceName(self, n_id: str): Returns: str: Name of device. """ + product_name = False + device_name = False + try: product_name = self.session.data.products[n_id]["state"]["name"] except KeyError: - product_name = False + pass try: device_name = self.session.data.devices[n_id]["state"]["name"] except KeyError: - device_name = False + pass + + if not product_name and not device_name: + _LOGGER.warning( + "getDeviceName - No product or device name found for ID: %s", n_id + ) if product_name: - return product_name + final_name = product_name elif device_name: - return device_name + final_name = device_name elif n_id == "No_ID": - return "Hive" + final_name = "Hive" else: - return n_id + final_name = n_id + + return final_name def deviceRecovered(self, n_id: str): """Register that a device has recovered from being offline. @@ -62,15 +74,16 @@ def deviceRecovered(self, n_id: str): async def errorCheck(self, n_id, n_type, error_type, **kwargs): """Error has occurred.""" message = None - name = self.getDeviceName(n_id) + name = await self.getDeviceName(n_id) + device_name = name if isinstance(name, str) else n_id if error_type is False: - message = "Device offline could not update entity - " + str(name) + message = "Device offline could not update entity - " + str(device_name) if n_id not in self.session.config.errorList: _LOGGER.warning(message) self.session.config.errorList.update({n_id: datetime.datetime.now()}) elif error_type == "Failed": - message = "ERROR - No data found for device - " + str(name) + message = "ERROR - No data found for device - " + str(device_name) if n_id not in self.session.config.errorList: _LOGGER.error(message) self.session.config.errorList.update({n_id: datetime.datetime.now()}) @@ -85,8 +98,13 @@ def getDeviceFromID(self, n_id: str): dict: Device data. """ if hasattr(self.session, "entityCache"): - for cached in self.session.entityCache.values(): + for cached_id, cached in self.session.entityCache.items(): if cached.get("hiveID") == n_id or cached.get("device_id") == n_id: + _LOGGER.debug( + "getDeviceFromID - Found cached device for ID %s: %s", + n_id, + cached.get("haName", cached_id), + ) return cached return False @@ -99,6 +117,7 @@ def getDeviceData(self, product: dict): Returns: [type]: Device data. """ + product_id = product.get("id", "Unknown") device = product type = product["type"] if type in ("heating", "hotwater"): @@ -110,13 +129,21 @@ def getDeviceData(self, product: dict): == self.session.data.devices[aDevice]["props"]["zone"] ): device = self.session.data.devices[aDevice] - except KeyError: + except KeyError as e: + _LOGGER.warning( + "getDeviceData - KeyError accessing zone data for device %s: %s", + aDevice, + str(e), + ) pass elif type == "trvcontrol": trv_present = len(product["props"]["trvs"]) > 0 if trv_present: device = self.session.data.devices[product["props"]["trvs"][0]] else: + _LOGGER.error( + "getDeviceData - No TRVs found for product %s", product_id + ) raise KeyError elif type == "warmwhitelight" and product["props"]["model"] == "SIREN001": device = self.session.data.devices[product["parent"]] @@ -152,6 +179,9 @@ def getScheduleNNL(self, hive_api_schedule: list): Returns: dict: Now, Next and later values. """ + _LOGGER.debug( + "getScheduleNNL - Parsing schedule NNL for %d days", len(hive_api_schedule) + ) schedule_now_and_next = {} date_time_now = datetime.datetime.now() date_time_now_day_int = date_time_now.today().weekday() @@ -167,6 +197,7 @@ def getScheduleNNL(self, hive_api_schedule: list): ) days_rolling_list = list(days_t[date_time_now_day_int:] + days_t)[:7] + _LOGGER.debug("getScheduleNNL - Days rolling list: %s", days_rolling_list) full_schedule_list = [] @@ -177,6 +208,11 @@ def getScheduleNNL(self, hive_api_schedule: list): key=operator.itemgetter("start"), reverse=False, ) + _LOGGER.debug( + "getScheduleNNL - Processing day %s with %d schedule slots", + days_rolling_list[day_index], + len(current_day_schedule_sorted), + ) for current_slot in range(0, len(current_day_schedule_sorted)): current_slot_custom = current_day_schedule_sorted[current_slot] @@ -199,21 +235,34 @@ def getScheduleNNL(self, hive_api_schedule: list): reverse=False, ) - schedule_now = fsl_sorted[-1] - schedule_next = fsl_sorted[0] - schedule_later = fsl_sorted[1] + if len(fsl_sorted) >= 3: + schedule_now = fsl_sorted[-1] + schedule_next = fsl_sorted[0] + schedule_later = fsl_sorted[1] - schedule_now["Start_DateTime"] = schedule_now[ - "Start_DateTime" - ] - datetime.timedelta(days=7) + schedule_now["Start_DateTime"] = schedule_now[ + "Start_DateTime" + ] - datetime.timedelta(days=7) - schedule_now["End_DateTime"] = schedule_next["Start_DateTime"] - schedule_next["End_DateTime"] = schedule_later["Start_DateTime"] - schedule_later["End_DateTime"] = fsl_sorted[2]["Start_DateTime"] + schedule_now["End_DateTime"] = schedule_next["Start_DateTime"] + schedule_next["End_DateTime"] = schedule_later["Start_DateTime"] + schedule_later["End_DateTime"] = fsl_sorted[2]["Start_DateTime"] - schedule_now_and_next["now"] = schedule_now - schedule_now_and_next["next"] = schedule_next - schedule_now_and_next["later"] = schedule_later + schedule_now_and_next["now"] = schedule_now + schedule_now_and_next["next"] = schedule_next + schedule_now_and_next["later"] = schedule_later + + _LOGGER.debug( + "getScheduleNNL - Schedule NNL parsed successfully - now: %s, next: %s, later: %s", + schedule_now.get("Start_DateTime"), + schedule_next.get("Start_DateTime"), + schedule_later.get("Start_DateTime"), + ) + else: + _LOGGER.warning( + "getScheduleNNL - Insufficient schedule data (%d slots) for NNL calculation", + len(fsl_sorted), + ) return schedule_now_and_next @@ -229,3 +278,49 @@ def getHeatOnDemandDevice(self, device: dict): trv = self.session.data.products.get(device["HiveID"]) thermostat = self.session.data.products.get(trv["state"]["zone"]) return thermostat + + def _sanitize_payload(self, payload: dict[str, Any]) -> dict[str, Any]: + """Return a copy of payload with sensitive values masked for logs.""" + + def _mask(value: Any) -> Any: + if isinstance(value, str): + if len(value) <= 8: + return "***" + return f"{value[:4]}...{value[-4:]}" + elif isinstance(value, dict): + return {k: _mask(v) for k, v in value.items()} + elif isinstance(value, list): + return [_mask(item) for item in value] + else: + return value + + def _walk(node: Any) -> Any: + if isinstance(node, dict): + result: dict[str, Any] = {} + for key, value in node.items(): + key_lower = key.lower() + if any( + part in key_lower + for part in ( + "password", + "token", + "tokens", + "secret", + "code", + "session", + "accesstoken", + "device_data", + "authenticationresult", + "responsemetadata", + "newdevicemetadata", + ) + ): + result[key] = _mask(value) + else: + result[key] = _walk(value) + return result + if isinstance(node, list): + return [_walk(item) for item in node] + return node + + return _walk(copy.deepcopy(payload)) diff --git a/src/hive.py b/src/hive.py index 29f2edd..30cdbeb 100644 --- a/src/hive.py +++ b/src/hive.py @@ -113,7 +113,7 @@ def __init__( self.light = Light(self.session) self.switch = Switch(self.session) self.sensor = Sensor(self.session) - _LOGGER.debug("Hive session initialised with all device handlers.") + if debug: sys.settrace(trace_debug) diff --git a/src/hotwater.py b/src/hotwater.py index 3976ae7..3c4e884 100644 --- a/src/hotwater.py +++ b/src/hotwater.py @@ -132,7 +132,9 @@ async def setMode(self, device: dict, new_mode: str): if device["hiveID"] in self.session.data.products: _LOGGER.debug( - "Setting hot water mode to %s for %s.", new_mode, device["haName"] + "setMode - Setting hot water mode to %s for %s.", + new_mode, + device["haName"], ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] @@ -163,7 +165,9 @@ async def setBoostOn(self, device: dict, mins: int): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting hot water boost ON for %s: %s mins.", device["haName"], mins + "setBoostOn - Setting hot water boost ON for %s: %s mins.", + device["haName"], + mins, ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] @@ -192,7 +196,9 @@ async def setBoostOff(self, device: dict): and await self.getBoost(device) == "ON" and device["deviceData"]["online"] ): - _LOGGER.debug("Setting hot water boost OFF for %s.", device["haName"]) + _LOGGER.debug( + "setBoostOff - Setting hot water boost OFF for %s.", device["haName"] + ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] prev_mode = data["props"]["previous"]["mode"] @@ -221,7 +227,7 @@ def __init__(self, session: object = None): """ self.session = session - async def getWaterHeater(self, device: dict): + async def getWaterHeater(self, device: dict): """Update water heater device. Args: @@ -230,23 +236,25 @@ async def getWaterHeater(self, device: dict): Returns: dict: Updated device. """ - if self.session.shouldUseCachedData(): - cached = self.session.getCachedDevice(device) - if cached is not None: - _LOGGER.debug( - "Returning cached state for water heater %s (slow/busy poll).", - device["haName"], - ) - return cached - device["deviceData"].update( - {"online": await self.session.attr.onlineOffline(device["device_id"])} - ) - - if device["deviceData"]["online"]: + if self.session.shouldUseCachedData(): + cached = self.session.getCachedDevice(device) + if cached is not None: + _LOGGER.debug( + "getWaterHeater - Returning cached state for water heater %s (slow/busy poll).", + device["haName"], + ) + return cached + device["deviceData"].update( + {"online": await self.session.attr.onlineOffline(device["device_id"])} + ) + + if device["deviceData"]["online"]: dev_data = {} self.session.helper.deviceRecovered(device["device_id"]) - _LOGGER.debug("Updating hot water data for %s.", device["haName"]) + _LOGGER.debug( + "getWaterHeater - Updating hot water data for %s.", device["haName"] + ) data = self.session.data.devices[device["device_id"]] dev_data = { "hiveID": device["hiveID"], @@ -265,13 +273,19 @@ async def getWaterHeater(self, device: dict): ), } - return self.session.setCachedDevice(device, dev_data) - else: - await self.session.helper.errorCheck( - device["device_id"], "ERROR", device["deviceData"]["online"] - ) - device.setdefault("status", {"current_operation": None}) - return device + _LOGGER.debug( + "getWaterHeater - Water heater device data for %s: %s", + device["haName"], + dev_data["status"], + ) + + return self.session.setCachedDevice(device, dev_data) + else: + await self.session.helper.errorCheck( + device["device_id"], "ERROR", device["deviceData"]["online"] + ) + device.setdefault("status", {"current_operation": None}) + return device async def getScheduleNowNextLater(self, device: dict): """Hive get hotwater schedule now, next and later. diff --git a/src/light.py b/src/light.py index b5ea001..ac31824 100644 --- a/src/light.py +++ b/src/light.py @@ -29,13 +29,16 @@ async def getState(self, device: dict): """ state = None final = None + device_name = device.get("haName", device.get("hiveID", "Unknown")) try: data = self.session.data.products[device["hiveID"]] state = data["state"]["status"] final = HIVETOHA[self.lightType].get(state, state) except KeyError as e: - _LOGGER.error(e) + _LOGGER.error( + "KeyError getting light state for %s: %s", device_name, str(e) + ) return final @@ -50,13 +53,16 @@ async def getBrightness(self, device: dict): """ state = None final = None + device_name = device.get("haName", device.get("hiveID", "Unknown")) try: data = self.session.data.products[device["hiveID"]] state = data["state"]["brightness"] final = (state / 100) * 255 except KeyError as e: - _LOGGER.error(e) + _LOGGER.error( + "KeyError getting light brightness for %s: %s", device_name, str(e) + ) return final @@ -176,24 +182,44 @@ async def setStatusOff(self, device: dict): device (dict): Device to turn off. Returns: - boolean: True/False if successful. + boolean: True/False if successful """ + device_name = device.get("haName", device.get("hiveID", "Unknown")) + _LOGGER.info("Turning off light %s", device_name) + + await self.session.hiveRefreshTokens() final = False if ( device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Turning light OFF for %s.", device["haName"]) - await self.session.hiveRefreshTokens() + _LOGGER.debug( + "setStatusOff - Device %s is online, proceeding with turn off", + device_name, + ) data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( data["type"], device["hiveID"], status="OFF" ) if resp["original"] == 200: - final = True + _LOGGER.debug( + "setStatusOff - Light turned off successfully for %s, refreshing device data", + device_name, + ) await self.session.getDevices(device["hiveID"]) + final = True + else: + _LOGGER.error( + "Failed to turn off light %s, response: %s", + device_name, + resp["original"], + ) + else: + _LOGGER.warning( + "Device %s not found or offline, cannot turn off", device_name + ) return final @@ -204,24 +230,44 @@ async def setStatusOn(self, device: dict): device (dict): Device to turn on. Returns: - boolean: True/False if successful. + boolean: True/False if successful """ + device_name = device.get("haName", device.get("hiveID", "Unknown")) + _LOGGER.info("Turning on light %s", device_name) + + await self.session.hiveRefreshTokens() final = False if ( device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Turning light ON for %s.", device["haName"]) - await self.session.hiveRefreshTokens() + _LOGGER.debug( + "setStatusOn - Device %s is online, proceeding with turn on", + device_name, + ) data = self.session.data.products[device["hiveID"]] - resp = await self.session.api.setState( data["type"], device["hiveID"], status="ON" ) + if resp["original"] == 200: - final = True + _LOGGER.debug( + "setStatusOn - Light turned on successfully for %s, refreshing device data", + device_name, + ) await self.session.getDevices(device["hiveID"]) + final = True + else: + _LOGGER.error( + "Failed to turn on light %s, response: %s", + device_name, + resp["original"], + ) + else: + _LOGGER.warning( + "Device %s not found or offline, cannot turn on", device_name + ) return final @@ -229,12 +275,16 @@ async def setBrightness(self, device: dict, n_brightness: int): """Set brightness of the light. Args: - device (dict): Device to set brightness for. - n_brightness (int): Brightness value + device (dict): Device to set brightness of. + n_brightness (int): Brightness value to set the light to. Returns: - boolean: True/False if successful. + boolean: True/False if successful """ + device_name = device.get("haName", device.get("hiveID", "Unknown")) + _LOGGER.info("Setting brightness to %s for light %s", n_brightness, device_name) + + await self.session.hiveRefreshTokens() final = False if ( @@ -242,16 +292,14 @@ async def setBrightness(self, device: dict, n_brightness: int): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting brightness to %s for %s.", n_brightness, device["haName"] + "setBrightness - Device %s is online, proceeding with brightness change", + device_name, ) - await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( - data["type"], - device["hiveID"], - status="ON", - brightness=n_brightness, + data["type"], device["hiveID"], status="ON", brightness=n_brightness ) + if resp["original"] == 200: final = True await self.session.getDevices(device["hiveID"]) @@ -275,7 +323,9 @@ async def setColorTemp(self, device: dict, color_temp: int): and device["deviceData"]["online"] ): _LOGGER.debug( - "Setting colour temperature to %s for %s.", color_temp, device["haName"] + "setColorTemp - Setting colour temperature to %s for %s.", + color_temp, + device["haName"], ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] @@ -316,7 +366,9 @@ async def setColor(self, device: dict, new_color: list): device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Setting colour to %s for %s.", new_color, device["haName"]) + _LOGGER.debug( + "setColor - Setting colour to %s for %s.", new_color, device["haName"] + ) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] @@ -363,7 +415,7 @@ async def getLight(self, device: dict): cached = self.session.getCachedDevice(device) if cached is not None: _LOGGER.debug( - "Returning cached state for light %s (slow/busy poll).", + "getLight - Returning cached state for light %s (slow/busy poll).", device["haName"], ) return cached @@ -374,7 +426,7 @@ async def getLight(self, device: dict): if device["deviceData"]["online"]: self.session.helper.deviceRecovered(device["device_id"]) - _LOGGER.debug("Updating light data for %s.", device["haName"]) + _LOGGER.debug("getLight - Updating light data for %s.", device["haName"]) data = self.session.data.devices[device["device_id"]] dev_data = { "hiveID": device["hiveID"], @@ -421,6 +473,11 @@ async def getLight(self, device: dict): "mode": await self.getColorMode(device), } ) + _LOGGER.debug( + "getLight - Light device data for %s: %s", + device["haName"], + dev_data["status"], + ) return self.session.setCachedDevice(device, dev_data) else: diff --git a/src/plug.py b/src/plug.py index 46d6c78..c95590c 100644 --- a/src/plug.py +++ b/src/plug.py @@ -71,7 +71,7 @@ async def setStatusOn(self, device: dict): device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Turning plug ON for %s.", device["haName"]) + _LOGGER.debug("setStatusOn - Turning plug ON for %s.", device["haName"]) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( @@ -98,7 +98,7 @@ async def setStatusOff(self, device: dict): device["hiveID"] in self.session.data.products and device["deviceData"]["online"] ): - _LOGGER.debug("Turning plug OFF for %s.", device["haName"]) + _LOGGER.debug("setStatusOff - Turning plug OFF for %s.", device["haName"]) await self.session.hiveRefreshTokens() data = self.session.data.products[device["hiveID"]] resp = await self.session.api.setState( @@ -139,7 +139,7 @@ async def getSwitch(self, device: dict): cached = self.session.getCachedDevice(device) if cached is not None: _LOGGER.debug( - "Returning cached state for switch %s (slow/busy poll).", + "getSwitch - Returning cached state for switch %s (slow/busy poll).", device["haName"], ) return cached @@ -150,7 +150,7 @@ async def getSwitch(self, device: dict): if device["deviceData"]["online"]: self.session.helper.deviceRecovered(device["device_id"]) - _LOGGER.debug("Updating switch data for %s.", device["haName"]) + _LOGGER.debug("getSwitch - Updating switch data for %s.", device["haName"]) data = self.session.data.devices[device["device_id"]] dev_data = { "hiveID": device["hiveID"], @@ -182,6 +182,12 @@ async def getSwitch(self, device: dict): } ) + _LOGGER.debug( + "getSwitch - Switch device data for %s: %s", + device["haName"], + dev_data["status"], + ) + return self.session.setCachedDevice(device, dev_data) else: await self.session.helper.errorCheck( diff --git a/src/sensor.py b/src/sensor.py index 296d16a..cc0546a 100644 --- a/src/sensor.py +++ b/src/sensor.py @@ -74,8 +74,8 @@ def __init__(self, session: object = None): """ self.session = session - async def getSensor(self, device: dict): - """Gets updated sensor data. + async def getSensor(self, device: dict): + """Gets updated sensor data. Args: device (dict): Device to update. @@ -83,18 +83,18 @@ async def getSensor(self, device: dict): Returns: dict: Updated device. """ - if self.session.shouldUseCachedData(): - cached = self.session.getCachedDevice(device) - if cached is not None: - _LOGGER.debug( - "Returning cached state for sensor %s (slow/busy poll).", - device["haName"], - ) - return cached - device["deviceData"].update( - {"online": await self.session.attr.onlineOffline(device["device_id"])} - ) - data = {} + if self.session.shouldUseCachedData(): + cached = self.session.getCachedDevice(device) + if cached is not None: + _LOGGER.debug( + "Returning cached state for sensor %s (slow/busy poll).", + device["haName"], + ) + return cached + device["deviceData"].update( + {"online": await self.session.attr.onlineOffline(device["device_id"])} + ) + data = {} if device["deviceData"]["online"] or device["hiveType"] in ( "Availability", @@ -104,7 +104,7 @@ async def getSensor(self, device: dict): self.session.helper.deviceRecovered(device["device_id"]) _LOGGER.debug( - "Updating sensor data for %s (%s).", + "getSensor - Updating sensor data for %s (%s).", device["haName"], device["hiveType"], ) @@ -154,10 +154,16 @@ async def getSensor(self, device: dict): } ) - return self.session.setCachedDevice(device, dev_data) - else: - await self.session.helper.errorCheck( - device["device_id"], "ERROR", device["deviceData"]["online"] - ) - device.setdefault("status", {"state": None}) - return device + _LOGGER.debug( + "getSensor - Sensor device data for %s: %s", + device["haName"], + dev_data["status"], + ) + + return self.session.setCachedDevice(device, dev_data) + else: + await self.session.helper.errorCheck( + device["device_id"], "ERROR", device["deviceData"]["online"] + ) + device.setdefault("status", {"state": None}) + return device diff --git a/src/session.py b/src/session.py index 3d55986..a61a8fd 100644 --- a/src/session.py +++ b/src/session.py @@ -11,7 +11,6 @@ from datetime import datetime, timedelta from aiohttp.web import HTTPException - from apyhiveapi import API, Auth from .device_attributes import HiveAttributes @@ -247,6 +246,9 @@ async def updateTokens(self, tokens: dict, update_expiry_time: bool = True): dict: Parsed dictionary of tokens """ data = {} + _LOGGER.debug( + "updateTokens - Input tokens: %s", self.helper._sanitize_payload(tokens) + ) if "AuthenticationResult" in tokens: data = tokens.get("AuthenticationResult") self.tokens.tokenData.update({"token": data["IdToken"]}) @@ -265,7 +267,7 @@ async def updateTokens(self, tokens: dict, update_expiry_time: bool = True): self.tokens.tokenExpiry = timedelta(seconds=data["ExpiresIn"]) _LOGGER.debug( - "updateTokens — IdToken: len=%d tail=…%s | " + "updateTokens — Final session tokens: IdToken: len=%d tail=…%s | " "AccessToken: len=%d tail=…%s | " "RefreshToken: %s | " "ExpiresIn: %s | tokenCreated: %s | tokenExpiry: %s", @@ -290,7 +292,14 @@ async def updateTokens(self, tokens: dict, update_expiry_time: bool = True): return self.tokens async def login(self): - """Login to hive account. + """Login to hive account with business logic routing. + + Business Rules: + 1) Login successfully - tokens returned, no device login or SMS2FA needed + 2) Check for device login or SMS challenges + 3) Direct flow to one of the two + 4) If device login, process ends but check if device is registered + 5) If SMS, follow on with device registration Raises: HiveUnknownConfiguration: Login information is unknown. @@ -302,7 +311,7 @@ async def login(self): if not self.auth: raise HiveUnknownConfiguration - _LOGGER.debug("Attempting login to Hive account.") + _LOGGER.debug("login - Attempting login to Hive account.") try: result = await self.auth.login() except HiveInvalidUsername: @@ -315,78 +324,122 @@ async def login(self): _LOGGER.error("Login failed: API error or no internet connection.") raise + # Rule 1: Login successful - tokens returned, no challenges needed if result and "AuthenticationResult" in result: auth_keys = list(result["AuthenticationResult"].keys()) - _LOGGER.debug("Login successful — AuthenticationResult keys: %s", auth_keys) + _LOGGER.debug( + "login - Login successful — AuthenticationResult keys: %s", auth_keys + ) await self.updateTokens(result) - return result + return result + + # Rule 2 & 3: Check for device login or SMS challenges and route + challenge_name = result.get("ChallengeName") + _LOGGER.debug("login - Challenge detected: %s", challenge_name) + + if challenge_name == self.auth.DEVICE_VERIFIER_CHALLENGE: + # Rule 4: Device login flow - check if device is registered + _LOGGER.debug("login - Routing to device login flow") + return await self._handleDeviceLoginChallenge(result) + elif challenge_name == self.auth.SMS_MFA_CHALLENGE: + # Rule 5: SMS flow - will need device registration after 2FA + _LOGGER.debug("login - Routing to SMS 2FA flow (requires user input)") + return result + else: + _LOGGER.error("login - Unsupported challenge: %s", challenge_name) + raise HiveUnknownConfiguration - async def sms2fa(self, code, session): - """Login to hive account with 2 factor authentication. + async def _handleDeviceLoginChallenge(self, login_result): + """Handle device login challenge. - Raises: - HiveUnknownConfiguration: Login information is unknown. + Args: + login_result (dict): Result from initial login with DEVICE_SRP_AUTH challenge. Returns: - dict: result of the authentication request. + dict: Authentication result with tokens. + + Raises: + HiveReauthRequired: If device login encounters SMS_MFA (device not remembered). + HiveInvalidDeviceAuthentication: If device is not registered. """ - result = None - if not self.auth: - _LOGGER.error("2FA failed: authentication not initialised.") - raise HiveUnknownConfiguration + _LOGGER.debug("_handleDeviceLoginChallenge - Processing device login") + + # Check if device is registered before attempting device login + is_registered = await self.auth.is_device_registered() + if not is_registered: + _LOGGER.warning( + "_handleDeviceLoginChallenge - Device not registered, " + "cannot complete device login. User must complete SMS 2FA." + ) + raise HiveInvalidDeviceAuthentication - _LOGGER.debug("Submitting 2FA code.") - try: - result = await self.auth.sms_2fa(code, session) - except HiveInvalid2FACode: - _LOGGER.error("2FA failed: invalid code entered.") - raise - except HiveApiError: - _LOGGER.error("2FA failed: API error or no internet connection.") - raise + # Device is registered, proceed with device login + _LOGGER.debug("_handleDeviceLoginChallenge - Device is registered, proceeding") + result = await self.auth.device_login() + + # Check if device login returned SMS_MFA challenge (device not remembered by Cognito) + if result and result.get("ChallengeName") == self.auth.SMS_MFA_CHALLENGE: + _LOGGER.error( + "_handleDeviceLoginChallenge - Device login failed: SMS MFA challenge detected. " + "Device is not remembered by Cognito. User must reauthenticate." + ) + raise HiveReauthRequired if result and "AuthenticationResult" in result: auth_keys = list(result["AuthenticationResult"].keys()) _LOGGER.debug( - "2FA login successful — AuthenticationResult keys: %s", auth_keys + "_handleDeviceLoginChallenge - Device login successful — AuthenticationResult keys: %s", + auth_keys, ) await self.updateTokens(result) + return result - async def deviceLogin(self): - """Login to hive account using device authentication. + async def sms2fa(self, code, session): + """Login to hive account with 2 factor authentication. + + After successful SMS 2FA, checks if device needs registration and + handles it automatically (Rule 5). Raises: HiveUnknownConfiguration: Login information is unknown. - HiveInvalidDeviceAuthentication: Device information is unknown. Returns: - dict: result of the authentication request. + dict: result of the authentication request with device data if registered. """ result = None if not self.auth: - _LOGGER.error("Device login failed: authentication not initialised.") + _LOGGER.error("2FA failed: authentication not initialised.") raise HiveUnknownConfiguration - _LOGGER.debug("Attempting device login.") + _LOGGER.debug("sms_2fa - Submitting 2FA code.") try: - result = await self.auth.device_login() - except HiveInvalidDeviceAuthentication: - _LOGGER.error("Device login failed: invalid device credentials.") + result = await self.auth.sms_2fa(code, session) + except HiveInvalid2FACode: + _LOGGER.error("2FA failed: invalid code entered.") + raise + except HiveApiError: + _LOGGER.error("2FA failed: API error or no internet connection.") raise if result and "AuthenticationResult" in result: auth_keys = list(result["AuthenticationResult"].keys()) _LOGGER.debug( - "Device login successful — AuthenticationResult keys: %s", auth_keys + "sms_2fa - 2FA login successful — AuthenticationResult keys: %s", + auth_keys, ) await self.updateTokens(result) + return result - async def _retryDeviceLogin(self): - """Attempt device login with retries and backoff. + async def _retryLogin(self): + """Attempt login with retries and backoff. + + This is called when token refresh fails. It attempts to login again, + which may succeed via device login or may require user interaction (SMS 2FA). Raises: + HiveReauthRequired: User interaction required (SMS 2FA challenge). HiveInvalidDeviceAuthentication: Device credentials are invalid. HiveApiError: API error or no internet connection. """ @@ -394,25 +447,38 @@ async def _retryDeviceLogin(self): for delay_s in (0, 5, 10): try: if delay_s: - _LOGGER.debug("Retrying device login in %s seconds.", delay_s) + _LOGGER.debug( + "_retryLogin - Retrying login in %s seconds.", delay_s + ) await asyncio.sleep(delay_s) - await self.deviceLogin() + result = await self.login() + + # Check if login returned SMS_MFA challenge (requires user interaction) + if ( + result + and result.get("ChallengeName") == self.auth.SMS_MFA_CHALLENGE + ): + _LOGGER.error( + "_retryLogin - Login requires SMS 2FA. User must reauthenticate." + ) + raise HiveReauthRequired + last_err = None break - except HiveInvalidDeviceAuthentication: + except (HiveInvalidUsername, HiveInvalidPassword): _LOGGER.error( - "Device login failed with invalid credentials, reauthentication required." + "_retryLogin - Login failed with invalid credentials, reauthentication required." ) + raise HiveReauthRequired + except HiveReauthRequired: + # Propagate reauthentication requirement immediately + raise except HiveApiError as err: - _LOGGER.error("Device login attempt failed: %s", err) + _LOGGER.error("_retryLogin - Login attempt failed: %s", err) last_err = err if last_err is not None: - _LOGGER.error( - "All device login retries exhausted, but device login may resolve the issue." - ) - # Don't raise HiveReauthRequired - let the caller handle the error - # Device login itself should resolve 403 issues when successful - return + _LOGGER.error("_retryLogin - All login retries exhausted.") + raise HiveReauthRequired from last_err await self.hiveRefreshTokens(force_refresh=True) @@ -435,7 +501,7 @@ async def hiveRefreshTokens(self, force_refresh: bool = False): ) # Refresh at 90% of token lifetime to prevent expiration during API calls _LOGGER.debug( - "Session token expiry time ( Current: %s | Expiry: %s)", + "hiveRefreshTokens - Session token expiry time ( Current: %s | Expiry: %s)", datetime.now(), expiry_time, ) @@ -449,7 +515,7 @@ async def hiveRefreshTokens(self, force_refresh: bool = False): return result actual_expiry = self.tokens.tokenCreated + self.tokens.tokenExpiry _LOGGER.debug( - "Session Token created: %s | Actual expiry: %s | " + "hiveRefreshTokens - Session Token created: %s | Actual expiry: %s | " "Early refresh (×%s): %s | Now: %s | Force refresh: %s", self.tokens.tokenCreated, actual_expiry, @@ -466,7 +532,7 @@ async def hiveRefreshTokens(self, force_refresh: bool = False): if result and "AuthenticationResult" in result: auth_keys = list(result["AuthenticationResult"].keys()) _LOGGER.debug( - "Token refresh — AuthenticationResult keys: %s", + "hiveRefreshTokens - Token refresh — AuthenticationResult keys: %s", auth_keys, ) await self.updateTokens(result) @@ -474,16 +540,16 @@ async def hiveRefreshTokens(self, force_refresh: bool = False): self.tokens.tokenCreated + self.tokens.tokenExpiry ) _LOGGER.debug( - "Session Token refresh successful. New expiry: %s", + "hiveRefreshTokens - Session Token refresh successful. New expiry: %s", new_expiry, ) except (HiveRefreshTokenExpired, HiveFailedToRefreshTokens) as exc: _LOGGER.warning( - "Session Token refresh failed (%s), falling back to device login.", + "Session Token refresh failed (%s), falling back to login.", type(exc).__name__, ) if not force_refresh: - await self._retryDeviceLogin() + await self._retryLogin() else: _LOGGER.error( "Token refresh failed during retry attempt, giving up." @@ -511,10 +577,7 @@ async def updateData(self, device: dict): if self.updateLock.locked() and ( self._updateTask is None or current_task is not self._updateTask ): - _LOGGER.debug( - "Poll already in progress — using cached device data for %s.", - device["hiveID"], - ) + _LOGGER.debug("updateData - Update poll already in progress") return updated async with self.updateLock: # Re-check after acquiring lock — another caller may have already updated @@ -523,7 +586,7 @@ async def updateData(self, device: dict): return updated self._updateTask = current_task try: - _LOGGER.debug("Polling Hive API for device updates.") + _LOGGER.debug("updateData - Polling Hive API for device updates.") updated = await self.getDevices(device["hiveID"]) if updated and len(self.deviceList["camera"]) > 0: for camera in self.data.camera: @@ -531,10 +594,12 @@ async def updateData(self, device: dict): if camera_device is not None: await self.getCamera(camera_device) if updated: - _LOGGER.debug("Device update completed successfully.") + _LOGGER.debug( + "updateData - Device update completed successfully." + ) else: _LOGGER.debug( - "Device update failed, will retry after scan interval." + "updateData - Device update failed, will retry after scan interval." ) finally: if self._updateTask is current_task: @@ -626,11 +691,12 @@ async def getDevices(self, n_id: str): try: if self.config.file: - _LOGGER.debug("Loading device data from file.") + _LOGGER.debug("getDevices - Loading device data from file.") api_resp_d = self.openFile("data.json") elif self.tokens is not None: + _LOGGER.debug("getDevices - Refreshing tokens before fetching devices.") await self.hiveRefreshTokens() - _LOGGER.debug("Fetching all devices from Hive API.") + _LOGGER.debug("getDevices - Fetching all devices from Hive API.") api_call_start = time.monotonic() try: api_resp_d = await self.api.getAll() @@ -639,13 +705,13 @@ async def getDevices(self, n_id: str): "Auth error (401/403) after token refresh, " "falling back to full device re-login." ) - await self._retryDeviceLogin() + await self._retryLogin() last_auth_err = None for api_retry_delay in (0, 5, 10): try: if api_retry_delay: _LOGGER.debug( - "Retrying API call in %ss after device re-login.", + "getDevices - Retrying API call in %ss after device re-login.", api_retry_delay, ) await asyncio.sleep(api_retry_delay) @@ -662,8 +728,8 @@ async def getDevices(self, n_id: str): raise HiveReauthRequired from last_auth_err api_call_duration = time.monotonic() - api_call_start if api_call_duration > self._slowPollThreshold: - _LOGGER.warning( - "Hive API response took %.1fs — marking poll as slow.", + _LOGGER.debug( + "getDevices - Hive API response took %.1fs — marking poll as slow.", api_call_duration, ) self._lastPollSlow = True @@ -700,7 +766,7 @@ async def getDevices(self, n_id: str): self.config.homeID = api_resp_p[hiveType]["homes"][0]["id"] _LOGGER.debug( - "API returned %d products, %d devices, %d actions.", + "getDevices - API returned %d products, %d devices, %d actions.", len(tmpProducts), len(tmpDevices), len(tmpActions), @@ -755,7 +821,10 @@ async def startSession(self, config: dict = None): """ if config is None: config = {} - _LOGGER.debug("Starting Hive session.") + _LOGGER.debug("startSession - Starting Hive session.") + _LOGGER.debug( + "startSession - Config: %s", self.helper._sanitize_payload(config) + ) await self.useFile(config.get("username", self.config.username)) await self.updateInterval( config.get("options", {}).get("scan_interval", self.config.scanInterval) @@ -763,6 +832,7 @@ async def startSession(self, config: dict = None): if config != {}: if "tokens" in config and not self.config.file: + _LOGGER.debug("startSession - Updating tokens from config") await self.updateTokens(config["tokens"], False) if "username" in config and not self.config.file: @@ -798,6 +868,8 @@ async def createDevices(self): Returns: list: List of devices """ + _LOGGER.info("createDevices - Starting device discovery process") + self.deviceList["parent"] = [] self.deviceList["alarm_control_panel"] = [] self.deviceList["binary_sensor"] = [] @@ -809,48 +881,127 @@ async def createDevices(self): self.deviceList["water_heater"] = [] hive_type = HIVE_TYPES["Thermo"] + HIVE_TYPES["Sensor"] + + # Find hub device first for aDevice in self.data["devices"]: if self.data["devices"][aDevice]["type"] == "hub": self.hub_id = aDevice + hub_name = ( + self.data["devices"][aDevice].get("state", {}).get("name", aDevice) + ) + _LOGGER.debug( + "createDevices - Found hub device: %s (ID: %s)", hub_name, aDevice + ) break + else: + _LOGGER.warning("createDevices - No hub device found in device list") + + # Process devices + device_count = 0 for aDevice in self.data["devices"]: d = self.data.devices[aDevice] + device_name = d.get("state", {}).get("name", aDevice) + device_type = d.get("type", "Unknown") + _LOGGER.debug( + "createDevices - Processing device: %s (%s - %s)", + device_name, + aDevice, + device_type, + ) + device_list = DEVICES.get(self.data.devices[aDevice]["type"], []) for code in device_list: - eval("self." + code) + try: + eval("self." + code) + except Exception as e: + _LOGGER.error( + "Failed to execute device code '%s' for %s: %s", + code, + device_name, + str(e), + ) if self.data["devices"][aDevice]["type"] in hive_type: self.config.battery.append(d["id"]) + _LOGGER.debug( + "createDevices - Added device %s to battery monitoring list", + device_name, + ) + + device_count += 1 + # Process actions if "action" in HIVE_TYPES["Switch"]: + _LOGGER.debug( + "createDevices - Processing %d actions", len(self.data["actions"]) + ) for action in self.data["actions"]: a = self.data["actions"][action] # noqa: F841 - eval("self." + ACTIONS) + try: + eval("self." + ACTIONS) + except Exception as e: + _LOGGER.error( + "Failed to execute action code for action %s: %s", + action, + str(e), + ) + # Process products hive_type = HIVE_TYPES["Heating"] + HIVE_TYPES["Switch"] + HIVE_TYPES["Light"] + product_count = 0 for aProduct in self.data.products: p = self.data.products[aProduct] if "error" in p: + _LOGGER.warning( + "Skipping product %s due to error: %s", aProduct, p["error"] + ) continue + + product_name = p.get("state", {}).get("name", aProduct) + product_type = p.get("type", "Unknown") + _LOGGER.debug( + "createDevices - Processing product: %s (%s - %s)", + product_name, + aProduct, + product_type, + ) + # Only consider single items or heating groups if ( p.get("isGroup", False) and self.data.products[aProduct]["type"] not in HIVE_TYPES["Heating"] ): + _LOGGER.debug( + "createDevices - Skipping group product currently not supported %s (type: %s)", + product_name, + product_type, + ) continue - product_list = PRODUCTS.get(self.data.products[aProduct]["type"], []) - product_name = self.data.products[aProduct]["state"].get("name", "Unknown") + + product_list = PRODUCTS.get(product_type, []) for code in product_list: try: eval("self." + code) except (NameError, AttributeError) as e: - _LOGGER.warning(f"Device {product_name} cannot be setup - {e}") + _LOGGER.warning( + "createDevices - Device %s cannot be setup - %s", + product_name, + e, + ) - if self.data.products[aProduct]["type"] in hive_type: + if product_type in hive_type: self.config.mode.append(p["id"]) + _LOGGER.debug( + "createDevices - Added product %s to mode list", product_name + ) - _LOGGER.debug( - "Device discovery found: %d parent, %d binary_sensor, %d climate, %d light, %d sensor, %d switch, %d water_heater", + product_count += 1 + + _LOGGER.info( + "Device discovery completed: %d devices, %d products processed. " + "Found: %d parent, %d binary_sensor, %d climate, %d light, %d sensor, %d switch, %d water_heater", + device_count, + product_count, len(self.deviceList.get("parent", [])), len(self.deviceList.get("binary_sensor", [])), len(self.deviceList.get("climate", [])),