From 5aa35b52cc7ed6a225ca2f40dd8c1f93827a47b5 Mon Sep 17 00:00:00 2001 From: Alexei Chetroi Date: Tue, 30 Jul 2019 15:19:24 -0400 Subject: [PATCH] ZHA log helper (#25543) * Logging helper. * Use log helper for ZHA entities. * Use log helper for ZHA core device. * Log helper for ZHA core channels. * Lint * ZHA fixture fix. --- .../components/zha/core/channels/__init__.py | 48 +++++++++---------- .../components/zha/core/channels/closures.py | 4 +- .../components/zha/core/channels/general.py | 27 +++-------- .../zha/core/channels/homeautomation.py | 2 +- .../components/zha/core/channels/hvac.py | 6 +-- .../components/zha/core/channels/security.py | 22 ++++----- homeassistant/components/zha/core/device.py | 44 +++++++---------- homeassistant/components/zha/core/helpers.py | 24 ++++++++++ .../components/zha/device_tracker.py | 2 +- homeassistant/components/zha/entity.py | 8 +++- homeassistant/components/zha/light.py | 4 -- homeassistant/components/zha/lock.py | 8 +--- tests/components/zha/common.py | 12 +++-- 13 files changed, 106 insertions(+), 105 deletions(-) diff --git a/homeassistant/components/zha/core/channels/__init__.py b/homeassistant/components/zha/core/channels/__init__.py index a3db90d75bf..f219a7823da 100644 --- a/homeassistant/components/zha/core/channels/__init__.py +++ b/homeassistant/components/zha/core/channels/__init__.py @@ -15,7 +15,7 @@ from homeassistant.core import callback from homeassistant.helpers.dispatcher import async_dispatcher_send from ..helpers import ( configure_reporting, construct_unique_id, - safe_read, get_attr_id_by_name, bind_cluster) + safe_read, get_attr_id_by_name, bind_cluster, LogMixin) from ..const import ( REPORT_CONFIG_DEFAULT, SIGNAL_ATTR_UPDATED, ATTRIBUTE_CHANNEL, EVENT_RELAY_CHANNEL, ZDO_CHANNEL @@ -25,15 +25,14 @@ from ..registries import CLUSTER_REPORT_CONFIGS _LOGGER = logging.getLogger(__name__) -def parse_and_log_command(unique_id, cluster, tsn, command_id, args): +def parse_and_log_command(channel, tsn, command_id, args): """Parse and log a zigbee cluster command.""" - cmd = cluster.server_commands.get(command_id, [command_id])[0] - _LOGGER.debug( - "%s: received '%s' command with %s args on cluster_id '%s' tsn '%s'", - unique_id, + cmd = channel.cluster.server_commands.get(command_id, [command_id])[0] + channel.debug( + "received '%s' command with %s args on cluster_id '%s' tsn '%s'", cmd, args, - cluster.cluster_id, + channel.cluster.cluster_id, tsn ) return cmd @@ -46,8 +45,7 @@ def decorate_command(channel, command): from zigpy.exceptions import DeliveryError try: result = await command(*args, **kwds) - _LOGGER.debug("%s: executed command: %s %s %s %s", - channel.unique_id, + channel.debug("executed command: %s %s %s %s", command.__name__, "{}: {}".format("with args", args), "{}: {}".format("with kwargs", kwds), @@ -55,9 +53,8 @@ def decorate_command(channel, command): return result except (DeliveryError, Timeout) as ex: - _LOGGER.debug( - "%s: command failed: %s exception: %s", - channel.unique_id, + channel.debug( + "command failed: %s exception: %s", command.__name__, str(ex) ) @@ -73,7 +70,7 @@ class ChannelStatus(Enum): INITIALIZED = 3 -class ZigbeeChannel: +class ZigbeeChannel(LogMixin): """Base channel for a Zigbee cluster.""" CHANNEL_NAME = None @@ -151,19 +148,12 @@ class ZigbeeChannel: ) await asyncio.sleep(uniform(0.1, 0.5)) - _LOGGER.debug( - "%s: finished channel configuration", - self._unique_id - ) + self.debug("finished channel configuration") self._status = ChannelStatus.CONFIGURED async def async_initialize(self, from_cache): """Initialize channel.""" - _LOGGER.debug( - 'initializing channel: %s from_cache: %s', - self._channel_name, - from_cache - ) + self.debug('initializing channel: from_cache: %s', from_cache) self._status = ChannelStatus.INITIALIZED @callback @@ -213,6 +203,11 @@ class ZigbeeChannel: ) return result.get(attribute) + def log(self, level, msg, *args): + msg = '[%s]: ' + msg + args = (self.unique_id, ) + args + _LOGGER.log(level, msg, *args) + def __getattr__(self, name): """Get attribute or a decorated cluster command.""" if hasattr(self._cluster, name) and callable( @@ -257,7 +252,7 @@ class AttributeListeningChannel(ZigbeeChannel): await super().async_initialize(from_cache) -class ZDOChannel: +class ZDOChannel(LogMixin): """Channel for ZDO events.""" def __init__(self, cluster, device): @@ -298,13 +293,18 @@ class ZDOChannel: """Initialize channel.""" entry = self._zha_device.gateway.zha_storage.async_get_or_create( self._zha_device) - _LOGGER.debug("entry loaded from storage: %s", entry) + self.debug("entry loaded from storage: %s", entry) self._status = ChannelStatus.INITIALIZED async def async_configure(self): """Configure channel.""" self._status = ChannelStatus.CONFIGURED + def log(self, level, msg, *args): + msg = '[%s:ZDO](%s): ' + msg + args = (self._zha_device.nwk, self._zha_device.model, ) + args + _LOGGER.log(level, msg, *args) + class EventRelayChannel(ZigbeeChannel): """Event relay that can be attached to zigbee clusters.""" diff --git a/homeassistant/components/zha/core/channels/closures.py b/homeassistant/components/zha/core/channels/closures.py index f2f8d07fde9..b2465a924e4 100644 --- a/homeassistant/components/zha/core/channels/closures.py +++ b/homeassistant/components/zha/core/channels/closures.py @@ -32,8 +32,8 @@ class DoorLockChannel(ZigbeeChannel): def attribute_updated(self, attrid, value): """Handle attribute update from lock cluster.""" attr_name = self.cluster.attributes.get(attrid, [attrid])[0] - _LOGGER.debug("%s: Attribute report '%s'[%s] = %s", - self.unique_id, self.cluster.name, attr_name, value) + self.debug("Attribute report '%s'[%s] = %s", + self.cluster.name, attr_name, value) if attrid == self._value_attribute: async_dispatcher_send( self._zha_device.hass, diff --git a/homeassistant/components/zha/core/channels/general.py b/homeassistant/components/zha/core/channels/general.py index 0bad5f17456..931bb94ef17 100644 --- a/homeassistant/components/zha/core/channels/general.py +++ b/homeassistant/components/zha/core/channels/general.py @@ -31,13 +31,7 @@ class OnOffChannel(ZigbeeChannel): @callback def cluster_command(self, tsn, command_id, args): """Handle commands received to this cluster.""" - cmd = parse_and_log_command( - self.unique_id, - self._cluster, - tsn, - command_id, - args - ) + cmd = parse_and_log_command(self, tsn, command_id, args) if cmd in ('off', 'off_with_effect'): self.attribute_updated(self.ON_OFF, False) @@ -87,11 +81,8 @@ class OnOffChannel(ZigbeeChannel): async def async_update(self): """Initialize channel.""" from_cache = not self.device.is_mains_powered - _LOGGER.debug( - "%s is attempting to update onoff state - from cache: %s", - self._unique_id, - from_cache - ) + self.debug("attempting to update onoff state - from cache: %s", + from_cache) self._state = bool( await self.get_attribute_value(self.ON_OFF, from_cache=from_cache)) await super().async_update() @@ -105,13 +96,7 @@ class LevelControlChannel(ZigbeeChannel): @callback def cluster_command(self, tsn, command_id, args): """Handle commands received to this cluster.""" - cmd = parse_and_log_command( - self.unique_id, - self._cluster, - tsn, - command_id, - args - ) + cmd = parse_and_log_command(self, tsn, command_id, args) if cmd in ('move_to_level', 'move_to_level_with_on_off'): self.dispatch_level_change(SIGNAL_SET_LEVEL, args[0]) @@ -130,8 +115,8 @@ class LevelControlChannel(ZigbeeChannel): @callback def attribute_updated(self, attrid, value): """Handle attribute updates on this cluster.""" - _LOGGER.debug("%s: received attribute: %s update with value: %i", - self.unique_id, attrid, value) + self.debug("received attribute: %s update with value: %s", + attrid, value) if attrid == self.CURRENT_LEVEL: self.dispatch_level_change(SIGNAL_SET_LEVEL, value) diff --git a/homeassistant/components/zha/core/channels/homeautomation.py b/homeassistant/components/zha/core/channels/homeautomation.py index e4b67dd0db7..c61659b9661 100644 --- a/homeassistant/components/zha/core/channels/homeautomation.py +++ b/homeassistant/components/zha/core/channels/homeautomation.py @@ -19,7 +19,7 @@ class ElectricalMeasurementChannel(AttributeListeningChannel): async def async_update(self): """Retrieve latest state.""" - _LOGGER.debug("%s async_update", self.unique_id) + self.debug("async_update") # This is a polling channel. Don't allow cache. result = await self.get_attribute_value('active_power', diff --git a/homeassistant/components/zha/core/channels/hvac.py b/homeassistant/components/zha/core/channels/hvac.py index 3da881e75d8..3eb535c608d 100644 --- a/homeassistant/components/zha/core/channels/hvac.py +++ b/homeassistant/components/zha/core/channels/hvac.py @@ -24,7 +24,7 @@ class FanChannel(ZigbeeChannel): try: await self.cluster.write_attributes({'fan_mode': value}) except DeliveryError as ex: - _LOGGER.error("%s: Could not set speed: %s", self.unique_id, ex) + self.error("Could not set speed: %s", ex) return async def async_update(self): @@ -41,8 +41,8 @@ class FanChannel(ZigbeeChannel): def attribute_updated(self, attrid, value): """Handle attribute update from fan cluster.""" attr_name = self.cluster.attributes.get(attrid, [attrid])[0] - _LOGGER.debug("%s: Attribute report '%s'[%s] = %s", - self.unique_id, self.cluster.name, attr_name, value) + self.debug("Attribute report '%s'[%s] = %s", + self.cluster.name, attr_name, value) if attrid == self._value_attribute: async_dispatcher_send( self._zha_device.hass, diff --git a/homeassistant/components/zha/core/channels/security.py b/homeassistant/components/zha/core/channels/security.py index a69ab692da5..e6823899c4c 100644 --- a/homeassistant/components/zha/core/channels/security.py +++ b/homeassistant/components/zha/core/channels/security.py @@ -27,9 +27,9 @@ class IASZoneChannel(ZigbeeChannel): "{}_{}".format(self.unique_id, SIGNAL_ATTR_UPDATED), state ) - _LOGGER.debug("Updated alarm state: %s", state) + self.debug("Updated alarm state: %s", state) elif command_id == 1: - _LOGGER.debug("Enroll requested") + self.debug("Enroll requested") res = self._cluster.enroll_response(0, 0) self._zha_device.hass.async_create_task(res) @@ -39,26 +39,24 @@ class IASZoneChannel(ZigbeeChannel): if self._zha_device.manufacturer == 'LUMI': return from zigpy.exceptions import DeliveryError - _LOGGER.debug("%s: started IASZoneChannel configuration", - self._unique_id) + self.debug("started IASZoneChannel configuration") await bind_cluster(self.unique_id, self._cluster) ieee = self._cluster.endpoint.device.application.ieee try: res = await self._cluster.write_attributes({'cie_addr': ieee}) - _LOGGER.debug( - "%s: wrote cie_addr: %s to '%s' cluster: %s", - self.unique_id, str(ieee), self._cluster.ep_attribute, + self.debug( + "wrote cie_addr: %s to '%s' cluster: %s", + str(ieee), self._cluster.ep_attribute, res[0] ) except DeliveryError as ex: - _LOGGER.debug( - "%s: Failed to write cie_addr: %s to '%s' cluster: %s", - self.unique_id, str(ieee), self._cluster.ep_attribute, str(ex) + self.debug( + "Failed to write cie_addr: %s to '%s' cluster: %s", + str(ieee), self._cluster.ep_attribute, str(ex) ) - _LOGGER.debug("%s: finished IASZoneChannel configuration", - self._unique_id) + self.debug("%s: finished IASZoneChannel configuration") await self.get_attribute_value('zone_type', from_cache=False) diff --git a/homeassistant/components/zha/core/device.py b/homeassistant/components/zha/core/device.py index 82585552aa7..bd748708395 100644 --- a/homeassistant/components/zha/core/device.py +++ b/homeassistant/components/zha/core/device.py @@ -24,6 +24,7 @@ from .const import ( POWER_SOURCE, QUIRK_APPLIED, QUIRK_CLASS, SERVER, SERVER_COMMANDS, SIGNAL_AVAILABLE, UNKNOWN_MANUFACTURER, UNKNOWN_MODEL, ZDO_CHANNEL, LQI, RSSI, LAST_SEEN, ATTR_AVAILABLE) +from .helpers import LogMixin _LOGGER = logging.getLogger(__name__) _KEEP_ALIVE_INTERVAL = 7200 @@ -37,7 +38,7 @@ class DeviceStatus(Enum): INITIALIZED = 2 -class ZHADevice: +class ZHADevice(LogMixin): """ZHA Zigbee device object.""" def __init__(self, hass, zigpy_device, zha_gateway): @@ -272,25 +273,21 @@ class ZHADevice: async def async_configure(self): """Configure the device.""" - _LOGGER.debug('%s: started configuration', self.name) + self.debug('started configuration') await self._execute_channel_tasks( self.get_channels_to_configure(), 'async_configure') - _LOGGER.debug('%s: completed configuration', self.name) + self.debug('completed configuration') entry = self.gateway.zha_storage.async_create_or_update(self) - _LOGGER.debug('%s: stored in registry: %s', self.name, entry) + self.debug('stored in registry: %s', entry) async def async_initialize(self, from_cache=False): """Initialize channels.""" - _LOGGER.debug('%s: started initialization', self.name) + self.debug('started initialization') await self._execute_channel_tasks( self.all_channels, 'async_initialize', from_cache) - _LOGGER.debug( - '%s: power source: %s', - self.name, - self.power_source - ) + self.debug('power source: %s', self.power_source) self.status = DeviceStatus.INITIALIZED - _LOGGER.debug('%s: completed initialization', self.name) + self.debug('completed initialization') async def _execute_channel_tasks(self, channels, task_name, *args): """Gather and execute a set of CHANNEL tasks.""" @@ -316,19 +313,9 @@ class ZHADevice: try: async with semaphore: await getattr(channel, func_name)(*args) - _LOGGER.debug('%s: channel: %s %s stage succeeded', - self.name, - "{}-{}".format( - channel.name, channel.unique_id), - func_name) + channel.debug("channel: '%s' stage succeeded", func_name) except Exception as ex: # pylint: disable=broad-except - _LOGGER.warning( - '%s channel: %s %s stage failed ex: %s', - self.name, - "{}-{}".format(channel.name, channel.unique_id), - func_name, - ex - ) + channel.warning("channel: '%s' stage failed ex: %s", func_name, ex) @callback def async_unsub_dispatcher(self): @@ -409,7 +396,7 @@ class ZHADevice: {attribute: value}, manufacturer=manufacturer ) - _LOGGER.debug( + self.debug( 'set: %s for attr: %s to cluster: %s for ept: %s - res: %s', value, attribute, @@ -419,7 +406,7 @@ class ZHADevice: ) return response except DeliveryError as exc: - _LOGGER.debug( + self.debug( 'failed to set attribute: %s %s %s %s %s', '{}: {}'.format(ATTR_VALUE, value), '{}: {}'.format(ATTR_ATTRIBUTE, attribute), @@ -444,7 +431,7 @@ class ZHADevice: else: response = await cluster.client_command(command, *args) - _LOGGER.debug( + self.debug( 'Issued cluster command: %s %s %s %s %s %s %s', '{}: {}'.format(ATTR_CLUSTER_ID, cluster_id), '{}: {}'.format(ATTR_COMMAND, command), @@ -455,3 +442,8 @@ class ZHADevice: '{}: {}'.format(ATTR_ENDPOINT_ID, endpoint_id) ) return response + + def log(self, level, msg, *args): + msg = '[%s](%s): ' + msg + args = (self.nwk, self.model, ) + args + _LOGGER.log(level, msg, *args) diff --git a/homeassistant/components/zha/core/helpers.py b/homeassistant/components/zha/core/helpers.py index ed9f3e9c86a..95a7469e8ff 100644 --- a/homeassistant/components/zha/core/helpers.py +++ b/homeassistant/components/zha/core/helpers.py @@ -207,3 +207,27 @@ def async_is_bindable_target(source_zha_device, target_zha_device): if any(bindable in bindables for bindable in matches): return True return False + + +class LogMixin: + """Log helper.""" + + def log(self, level, msg, *args): + """Log with level.""" + raise NotImplementedError + + def debug(self, msg, *args): + """Debug level log.""" + return self.log(logging.DEBUG, msg, *args) + + def info(self, msg, *args): + """Info level log.""" + return self.log(logging.INFO, msg, *args) + + def warning(self, msg, *args): + """Warning method log.""" + return self.log(logging.WARNING, msg, *args) + + def error(self, msg, *args): + """Error level log.""" + return self.log(logging.ERROR, msg, *args) diff --git a/homeassistant/components/zha/device_tracker.py b/homeassistant/components/zha/device_tracker.py index 677b1bc1f27..3b9f8f916bf 100644 --- a/homeassistant/components/zha/device_tracker.py +++ b/homeassistant/components/zha/device_tracker.py @@ -91,7 +91,7 @@ class ZHADeviceScannerEntity(ScannerEntity, ZhaEntity): @callback def async_battery_percentage_remaining_updated(self, value): """Handle tracking.""" - _LOGGER.debug('battery_percentage_remaining updated: %s', value) + self.debug('battery_percentage_remaining updated: %s', value) self._connected = True self._battery_level = battery_percentage_remaining_formatter(value) self.async_schedule_update_ha_state() diff --git a/homeassistant/components/zha/entity.py b/homeassistant/components/zha/entity.py index 77cb5b8deda..c38c8aaffbb 100644 --- a/homeassistant/components/zha/entity.py +++ b/homeassistant/components/zha/entity.py @@ -14,6 +14,7 @@ from homeassistant.util import slugify from .core.const import ( ATTR_MANUFACTURER, DATA_ZHA, DATA_ZHA_BRIDGE_ID, DOMAIN, MODEL, NAME, SIGNAL_REMOVE) +from .core.helpers import LogMixin _LOGGER = logging.getLogger(__name__) @@ -21,7 +22,7 @@ ENTITY_SUFFIX = 'entity_suffix' RESTART_GRACE_PERIOD = 7200 # 2 hours -class ZhaEntity(RestoreEntity, entity.Entity): +class ZhaEntity(RestoreEntity, LogMixin, entity.Entity): """A base class for ZHA entities.""" _domain = None # Must be overridden by subclasses @@ -186,3 +187,8 @@ class ZhaEntity(RestoreEntity, entity.Entity): func ) self._unsubs.append(unsub) + + def log(self, level, msg, *args): + msg = '%s: ' + msg + args = (self.entity_id, ) + args + _LOGGER.log(level, msg, *args) diff --git a/homeassistant/components/zha/light.py b/homeassistant/components/zha/light.py index 9e0f2739290..5204fb10182 100644 --- a/homeassistant/components/zha/light.py +++ b/homeassistant/components/zha/light.py @@ -273,7 +273,3 @@ class Light(ZhaEntity, light.Light): async def refresh(self, time): """Call async_get_state at an interval.""" await self.async_get_state(from_cache=False) - - def debug(self, msg, *args): - """Log debug message.""" - _LOGGER.debug('%s: ' + msg, self.entity_id, *args) diff --git a/homeassistant/components/zha/lock.py b/homeassistant/components/zha/lock.py index 5ac4a0c2e30..c32ae358aea 100644 --- a/homeassistant/components/zha/lock.py +++ b/homeassistant/components/zha/lock.py @@ -95,7 +95,7 @@ class ZhaDoorLock(ZhaEntity, LockDevice): """Lock the lock.""" result = await self._doorlock_channel.lock_door() if not isinstance(result, list) or result[0] is not Status.SUCCESS: - _LOGGER.error("Error with lock_door: %s", result) + self.error("Error with lock_door: %s", result) return self.async_schedule_update_ha_state() @@ -103,7 +103,7 @@ class ZhaDoorLock(ZhaEntity, LockDevice): """Unlock the lock.""" result = await self._doorlock_channel.unlock_door() if not isinstance(result, list) or result[0] is not Status.SUCCESS: - _LOGGER.error("Error with unlock_door: %s", result) + self.error("Error with unlock_door: %s", result) return self.async_schedule_update_ha_state() @@ -128,7 +128,3 @@ class ZhaDoorLock(ZhaEntity, LockDevice): async def refresh(self, time): """Call async_get_state at an interval.""" await self.async_get_state(from_cache=False) - - def debug(self, msg, *args): - """Log debug message.""" - _LOGGER.debug('%s: ' + msg, self.entity_id, *args) diff --git a/tests/components/zha/common.py b/tests/components/zha/common.py index 4cc7dec1edf..9250b8bba07 100644 --- a/tests/components/zha/common.py +++ b/tests/components/zha/common.py @@ -1,11 +1,14 @@ """Common test objects.""" import time -from unittest.mock import patch, Mock -from homeassistant.components.zha.core.helpers import convert_ieee +from unittest.mock import Mock, patch + +from asynctest import CoroutineMock + from homeassistant.components.zha.core.const import ( - DATA_ZHA, DATA_ZHA_CONFIG, DATA_ZHA_DISPATCHERS, DATA_ZHA_BRIDGE_ID -) + DATA_ZHA, DATA_ZHA_BRIDGE_ID, DATA_ZHA_CONFIG, DATA_ZHA_DISPATCHERS) +from homeassistant.components.zha.core.helpers import convert_ieee from homeassistant.util import slugify + from tests.common import mock_coro @@ -57,6 +60,7 @@ class FakeEndpoint: def patch_cluster(cluster): """Patch a cluster for testing.""" + cluster.bind = CoroutineMock(return_value=[0]) cluster.deserialize = Mock() cluster.handle_cluster_request = Mock() cluster.handle_cluster_general_request = Mock()