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.

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."""

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,

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)
 

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',

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,

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)
 

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)

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)

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()

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)

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)

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)

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()