Adds ALL-Link Group updates from external controllers

* Resolves nugget#114
* Increases ALDB reading timeout to 120s
* Handles reception of ALL-Link group broadcasts and cleanups
    correctly updating each responding device
* Requires device ALDB scan to get devices updated correctly; will
    work OK without the scan but individual devices should be hidden
    on the UI because they will not follow the scene correctly.
* Requires an update to the Home Assistant Insteon platform

Author: mstovenour

Diff for: insteonplm/devices/__init__.py

@@ -27,8 +27,8 @@
     MESSAGE_TYPE_ALL_LINK_CLEANUP,
     MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0,
     MESSAGE_STANDARD_MESSAGE_RECEIVED_0X50,
-    MESSAGE_EXTENDED_MESSAGE_RECEIVED_0X51
-)
+    MESSAGE_EXTENDED_MESSAGE_RECEIVED_0X51,
+    MESSAGE_TYPE_ALL_LINK_BROADCAST)
 from insteonplm.messagecallback import MessageCallback
 from insteonplm.messages.allLinkComplete import AllLinkComplete
 from insteonplm.messages.extendedReceive import ExtendedReceive
@@ -43,7 +43,7 @@
 DIRECT_ACK_WAIT_TIMEOUT = 3
 ALDB_RECORD_TIMEOUT = 10
 ALDB_RECORD_RETRIES = 20
-ALDB_ALL_RECORD_TIMEOUT = 30
+ALDB_ALL_RECORD_TIMEOUT = 120
 ALDB_ALL_RECORD_RETRIES = 5
 
 
@@ -215,9 +215,9 @@ def ALL_Link_cleanup(self, group, cmd_tuple):
                       self.address.human, group)
         flags = MessageFlags.template(MESSAGE_TYPE_ALL_LINK_CLEANUP, 0, 3, 3)
         msg = StandardSend(self._address, cmd_tuple, cmd2=group, flags=flags)
-        self._send_msg(msg, self._handle_ALL_Link_cleanup_ack)
+        self._send_msg(msg, self._handle_ALL_Link_cleanup)
 
-    def _handle_ALL_Link_cleanup_ack(self, msg):
+    def _handle_ALL_Link_cleanup(self, msg):
         _LOGGER.debug('Received ALL-Link Cleanup ACK from %s; ALL-Link group '
                       '0x%x; looking for responder states',
                       msg.address.human, msg.cmd2)
@@ -226,16 +226,10 @@ def _handle_ALL_Link_cleanup_ack(self, msg):
         responders = self._find_group_responder_states(msg.target, msg.cmd2)
 
         for responder in responders:
-            _LOGGER.debug('Calling %s:0x%x:handle_ALL_Link_cleanup_ack',
+            _LOGGER.debug('Calling %s:0x%02x:handle_ALL_Link_cleanup',
                           self._address.human, responder)
-            if hasattr(self.states[responder], 'handle_ALL_Link_cleanup_ack'):
-                self.states[responder].handle_ALL_Link_cleanup_ack(
-                    msg, responders[responder])
-            else:
-                _LOGGER.warning('Device %s:0x%x has no '
-                                'handle_ALL_Link_cleanup_ack() method.  '
-                                'Cannot perform ALL-Link cleanup',
-                                self._address.human, responder)
+            self.states[responder].handle_ALL_Link_cleanup(
+                msg, responders[responder])
 
     def _find_group_responder_states(self, ctl, ctl_group):
         _LOGGER.debug('Looking for responder to controller %s:0x%x',
@@ -729,11 +723,21 @@ def _register_messages(self):
         self._message_callbacks.add(template_all_link_complete,
                                     self._handle_all_link_complete)
 
+        template_All_Link_broadcast = StandardReceive.template(
+            flags=MessageFlags.template(MESSAGE_TYPE_ALL_LINK_CLEANUP, None))
+        self._message_callbacks.add(template_All_Link_broadcast,
+                                    self._handle_All_Link_broadcast)
+
+        template_All_Link_cleanup = StandardReceive.template(
+            flags=MessageFlags.template(MESSAGE_TYPE_ALL_LINK_BROADCAST, None))
+        self._message_callbacks.add(template_All_Link_cleanup,
+                                    self._handle_All_Link_broadcast)
+
     # Send / Receive message processing
     def receive_message(self, msg):
         """Receive a messages sent to this device."""
         _LOGGER.debug('Starting Device.receive_message for %s',
-                      msg.address.human)
+                      self.address.human)
         if hasattr(msg, 'isack') and msg.isack:
             _LOGGER.debug('Got Message ACK %s', id(msg))
             if self._sent_msg_wait_for_directACK.get('callback') is not None:
@@ -800,8 +804,24 @@ def _is_duplicate(self, msg):
             if msg.matches_pattern(prev_msg):
                 ret_val = True
 
+        # Add current message to recent list
         self._recent_messages.put_nowait(
             {"msg": msg, "received": datetime.datetime.now()})
+
+        # If an ALL-Link Broadcast was successfully received the ALL-Link
+        # cleanup should be considered a duplicate if not a 0x06 status report
+        if(msg.flags.isAllLinkBroadcast and msg.cmd1 != MESSAGE_ACK):
+            # Fabricate duplicate all-link cleanup
+            dup_target = self._plm.address
+            dup_group = msg.targetHi
+            dup_flags = MessageFlags.template(MESSAGE_TYPE_ALL_LINK_CLEANUP,
+                                              0, 3, 3)
+            dup_msg = StandardReceive(msg.address, dup_target,
+                                      {'cmd1': msg.cmd1, 'cmd2': dup_group},
+                                      flags=dup_flags)
+            self._recent_messages.put_nowait(
+                {"msg": dup_msg, "received": datetime.datetime.now()})
+
         return ret_val
 
     def _send_msg(self, msg, callback=None, on_timeout=False):
@@ -870,6 +890,88 @@ async def _wait_for_direct_ACK(self):
     def _aldb_loaded_callback(self):
         self._plm.devices.save_device_info()
 
+    def _handle_All_Link_broadcast(self, msg):
+        """Process ALL-Link broadcast or cleanup received from devices.
+
+        Parameters:
+        msg.address: controller's address
+        msg.targetHi: group triggered on controller for broadcast msg
+        msg.cmd2: group triggers on controller for clean up msg
+
+        Searches for controller's address and group triggered in this devices
+        ALDB to find this devices responding group.
+
+        """
+        if msg.cmd1 != MESSAGE_ACK:  # Ignore 0x06 status reports
+
+            # Don't bother searching the ALDB if there isn't at least one
+            # state that can respond to controllers
+            responder = False
+            for state in self._stateList:
+                if self._stateList[state].is_responder:
+                    responder = True
+                    break
+
+            if responder:
+                ctl_group = msg.targetHi
+                _LOGGER.debug('_handle_All_Link_broadcast msg: %s for '
+                              'device %s', id(msg), self.address.human)
+                if not ctl_group:
+                    # Not a broadcast message so must be a cleanup
+                    ctl_group = msg.cmd2
+
+                resp_groups = self._find_responder_groups(msg.address,
+                                                          ctl_group)
+                for resp_group in resp_groups:
+                    if self._stateList[resp_group]:
+                        self._stateList[resp_group].handle_ALL_Link_cleanup(
+                            msg, resp_groups[resp_group])
+                    else:
+                        _LOGGER.warning('ALDB Responder record maps to '
+                                        'nonexistent state')
+
+    def _find_responder_groups(self, ctl_address, ctl_group):
+        """Identify which PLM group responds to ctl / ctl_group.
+
+        Parameters:
+        ctl_address: address object of controller that sent ALL-Link command
+        ctl_group: group that was triggered on the controller
+
+        Returns:
+        dictionary of all responding groups on this device
+            key: responding group on this device from data3
+            value: recall_level from data1
+
+        NOTE:  The IM class overrides this method for the PLM's underlying
+        device object.
+
+        """
+        _LOGGER.debug('_find_responder_groups: looking for ctl: %s, '
+                      'ctl_group: 0x%02x on device %s', ctl_address.human,
+                      ctl_group, self.address.human)
+        groups = {}
+        if self._aldb:
+            for rec_num in self._aldb:
+                rec = self._aldb[rec_num]
+                if(rec.control_flags.is_responder and
+                   rec.group == ctl_group and
+                   rec.address == ctl_address):
+                    # Recall level is stored in data1
+                    # This device's group is stored in data3
+                    data3 = rec.data3 if rec.data3 != 0 else 1
+                    groups[data3] = rec.data1
+            _LOGGER.debug('Found %d responders on device %s', len(groups),
+                          self.address.human)
+        else:
+            if self._aldb.status == ALDBStatus.LOADED:
+                _LOGGER.warning('No responders found; ALDB is empty %s',
+                                self.address.human)
+            else:
+                _LOGGER.warning('No responders found; ALDB is not loaded %s',
+                                self.address.human)
+
+        return groups
+
 
 # pylint: disable=too-many-instance-attributes
 class X10Device():

Diff for: insteonplm/plm.py

@@ -13,7 +13,8 @@
                                   X10CommandType,
                                   X10_COMMAND_ALL_UNITS_OFF,
                                   X10_COMMAND_ALL_LIGHTS_ON,
-                                  X10_COMMAND_ALL_LIGHTS_OFF)
+                                  X10_COMMAND_ALL_LIGHTS_OFF,
+                                  MESSAGE_STANDARD_MESSAGE_RECEIVED_0X50)
 from insteonplm.address import Address
 from insteonplm.devices import Device, ALDBRecord, ALDBStatus
 from insteonplm.linkedDevices import LinkedDevices
@@ -650,10 +651,20 @@ async def _peel_messages_from_buffer(self):
     def _process_recv_queue(self):
         msg = self._recv_queue.pop()
         _LOGGER.debug('RX: %s:%s', id(msg), msg)
-        callbacks = self._message_callbacks.get_callbacks_from_message(msg)
         if hasattr(msg, 'isack') or hasattr(msg, 'isnak'):
             self._acknak_queue.put_nowait(msg)
-        if hasattr(msg, 'address'):
+
+        if(msg.code == MESSAGE_STANDARD_MESSAGE_RECEIVED_0X50 and
+           (msg.flags.isAllLinkBroadcast or msg.flags.isAllLinkCleanup)):
+            # Each device should look at the responder entries in its ALDB
+            # to see if the device should respond to this sender/sender group
+            # Responding means updating subscribers with the correct level
+            if msg.cmd1 != MESSAGE_ACK:  # not 0x06 status report
+                for device in self.devices:
+                    if self.devices[device]:
+                        self.devices[device].receive_message(msg)
+
+        elif hasattr(msg, 'address'):
             device = self.devices[msg.address.hex]
             if device:
                 device.receive_message(msg)
@@ -664,8 +675,51 @@ def _process_recv_queue(self):
                         device.receive_message(msg)
                 except KeyError:
                     pass
-        for callback in callbacks:
-            self._loop.call_soon(callback, msg)
+
+        # This check is a hack because message processing is not isolated
+        # between IM and Device (nugget/python-insteonplm#203)
+        if(msg.code != MESSAGE_STANDARD_MESSAGE_RECEIVED_0X50 or not
+           (msg.flags.isAllLinkBroadcast or msg.flags.isAllLinkCleanup)):
+            callbacks = self._message_callbacks.get_callbacks_from_message(msg)
+            for callback in callbacks:
+                _LOGGER.debug('Scheduling msg callback: %s', callback)
+                self._loop.call_soon(callback, msg)
+
+    def _find_responder_groups(self, ctl_address, ctl_group):
+        """Identify which PLM group responds to ctl / ctl_group.
+
+        Parameters:
+        ctl_address: address object of controller that sent ALL-Link command
+        ctl_group: group that was triggered on the controller
+
+        Returns:
+        dictionary of all responding groups on this device
+            key: responding group on this device from data3
+            value: recall_level from data1
+
+        NOTE: This overrides the same method in Device because the PLM requires
+        different logic for finding the responder groups.  The PLM does not
+        store the local responding group in its responder records (devices do
+        this).  The only option is to look for all matching "controller"
+        entries.  This assumes if PLM is controller it must also be responder
+        for the ALL-Link group.
+
+        """
+        _LOGGER.debug('_find_responder_groups: looking for ctl: %s, '
+                      'ctl_group: 0x%x on device %s', ctl_address.human,
+                      ctl_group, self.address.human)
+        groups = {}
+        for rec_num in self._aldb:
+            rec = self._aldb[rec_num]
+            if (rec.control_flags.is_controller and rec.data1 == ctl_group and
+                    rec.address == ctl_address):
+                # Recall level is always "on" for PLM responders
+                groups[rec.group] = 0xff
+
+        _LOGGER.debug('Found %d responders on device %s', len(groups),
+                      self.address.human)
+
+        return groups
 
     def _unpack_buffer(self):
         buffer = bytearray()

Diff for: insteonplm/states/__init__.py

@@ -116,12 +116,19 @@ def register_updates(self, callback):
         _LOGGER.debug("Registered callback for state: %s", self._stateName)
         self._observer_callbacks.append(callback)
 
+    # pylint: disable=unused-argument
+    def handle_ALL_Link_cleanup(self, msg, recall_level):
+        """Update the state's subscribers with the new level or fixed level."""
+        _LOGGER.warning('State %s has no handle_ALL_Link_cleanup() method.  '
+                        'Cannot perform ALL-Link cleanup',
+                        self.__class__.__name__)
+
     def _update_subscribers(self, val):
         """Save state value and notify listeners of the change."""
         self._value = val
         for callback in self._observer_callbacks:
-            _LOGGER.debug('_update_subscribers state %s:0x%x updating '
-                          'subscribers with level 0x%x', self.address.human,
+            _LOGGER.debug('_update_subscribers state %s:0x%02x updating '
+                          'subscribers with level 0x%02x', self.address.human,
                           self.group, val)
 
             callback(self._address, self._group, val)

Diff for: insteonplm/states/allLinkGroup.py

@@ -139,12 +139,40 @@ def dim(self):
         self._ALL_Link_cleanup_method(self.group,
                                       COMMAND_LIGHT_DIM_ONE_STEP_0X16_0X00)
 
+    def handle_ALL_Link_cleanup(self, msg, recall_level):
+        """Update the state's subscribers with the new level or fixed level."""
+        level = 255
+        if msg.cmd1 == COMMAND_LIGHT_ON_0X11_NONE.get('cmd1', None):
+            level = recall_level
+        elif msg.cmd1 == COMMAND_LIGHT_ON_FAST_0X12_NONE.get('cmd1', None):
+            level = 255
+        elif msg.cmd1 == COMMAND_LIGHT_OFF_0X13_0X00.get('cmd1', None):
+            level = 0
+        elif msg.cmd1 == COMMAND_LIGHT_OFF_FAST_0X14_0X00.get('cmd1', None):
+            level = 0
+        else:
+            _LOGGER.error('AlL-Link_cleanup device %s:0x%02x command '
+                          'unknown 0x%02x', msg.address.human, self.group,
+                          msg.cmd1)
+
+        _LOGGER.debug('AlL-Link_cleanup device %s:0x%02x updating '
+                      'subscribers with level 0x%x from command 0x%02x',
+                      self.address.human, self.group, level, msg.cmd1)
+
+        self._update_subscribers(level)
+
+    # pylint: disable=unused-argument
     def _on_message_received(self, msg):
-        cmd2 = msg.cmd2 if msg.cmd2 else 255
-        self._update_subscribers(cmd2)
+        _LOGGER.debug('AlL-Link_cleanup received device %s:0x%x updating '
+                      'subscribers with level 0x%x from command 0x%x',
+                      self.address.human, self.group, 0xff, msg.cmd1)
+        self._update_subscribers(0xff)
 
     # pylint: disable=unused-argument
     def _off_message_received(self, msg):
+        _LOGGER.debug('AlL-Link_cleanup received device %s:0x%x updating '
+                      'subscribers with level 0x%x from command 0x%x',
+                      self.address.human, self.group, 0x00, msg.cmd1)
         self._update_subscribers(0x00)
 
     # pylint: disable=unused-argument
@@ -159,5 +187,4 @@ def _send_status_request(self):
                           self._status_message_received)
 
     def _status_message_received(self, msg):
-        _LOGGER.debug("DimmableSwitch status message received called")
         self._update_subscribers(msg.cmd2)

Diff for: insteonplm/states/dimmable.py

@@ -237,8 +237,8 @@ def _status_message_received(self, msg):
         _LOGGER.debug("DimmableSwitch status message received called")
         self._update_subscribers(msg.cmd2)
 
-    def handle_ALL_Link_cleanup_ack(self, msg, recall_level):
-        """Update the state's subscribers with the new level.
+    def handle_ALL_Link_cleanup(self, msg, recall_level):
+        """Update the state's subscribers with the new level or a fixed level.
 
         For the ALL-Link recall message, the recall level is set during the
         devices ALDB discovery.  If ALDB has not been read, the default level

Diff for: insteonplm/states/onOff.py

@@ -82,8 +82,8 @@ def _status_message_received(self, msg):
         else:
             self._update_subscribers(0xff)
 
-    def handle_ALL_Link_cleanup_ack(self, msg, recall_level):
-        """Update the states subscribers with the new level.
+    def handle_ALL_Link_cleanup(self, msg, recall_level):
+        """Update the states subscribers with the new level or a fixed level.
 
         For the ALL-Link recall message, the recall level is set during the
         devices ALDB discovery.  If ALDB has not been read, the default level

Diff for: insteonplm/tools.py

@@ -125,7 +125,7 @@ def async_new_device_callback(self, device):
     # pylint: disable=no-self-use
     def async_state_change_callback(self, addr, state, value):
         """Log the state change."""
-        _LOGGING.info('Device %s state 0x%x value is changed to %s',
+        _LOGGING.info('Device %s state 0x%02x value is changed to %s',
                       addr.human, state, value)
 
     def async_aldb_loaded_callback(self):
@@ -775,7 +775,6 @@ async def do_load_aldb(self, args):
             addr = params[0]
         except IndexError:
             _LOGGING.error('Device address required.')
-            self.do_help('load_aldb')
 
         try:
             clear_prior = params[1]