Message handling (#89)

* Refactor message write process and remvoe some logging

* Clean up message processing

* flake8 and pylint fixes

* Startup process changes

* Reset get_next_all_link_rec NAK count on record received

* Refresh ALDB on All-Link complete

* Bump version to 0.12.1

* Update for multiple get_next_all_link_record NAKs

Author: teharris1

insteonplm/__init__.py

@@ -8,7 +8,6 @@
 import binascii
 from contextlib import suppress
 import logging
-import serial
 from serial.aio import create_serial_connection
 
 from insteonplm.plm import PLM, Hub
@@ -176,7 +175,7 @@ def _connect(self):
         if self.host:
             connected = yield from self._connect_http()
         else:
-            connected =  yield from self._connect_serial()
+            connected = yield from self._connect_serial()
         _LOGGER.debug('ending Connection._connect')
         return connected
 
@@ -333,7 +332,6 @@ def _async_write(self, url):
             _LOGGER.error('Reconnect to Hub (TimeoutError)')
             yield from self._stop_reader(True)
 
-
         if self._read_write_lock.locked():
             self._read_write_lock.release()
         return return_status
@@ -391,7 +389,7 @@ def _ensure_reader(self):
                     bin_buffer = binascii.unhexlify(buffer)
                     self._protocol.data_received(bin_buffer)
                 yield from asyncio.sleep(1, loop=self._loop)
-            
+
             except asyncio.CancelledError:
                 _LOGGER.debug('Stop connection to Hub (loop stopped)')
                 yield from self._stop_reader(False)
@@ -468,16 +466,16 @@ def _stop_reader(self, reconnect=False):
             _LOGGER.debug("We want to reconnect so we do...")
             self._protocol.connection_lost(True)
 
-    def _log_error(self, error):
+    def _log_error(self, status):
         # TODO: handle other status codes
-        if response.status == 401:
+        if status == 401:
             _LOGGER.error('Athentication error, check your configuration')
             _LOGGER.error('If configuration is correct and restart the Hub')
             _LOGGER.error('System must be restared to reconnect to hub')
-        elif response.status == 404:
+        elif status == 404:
             _LOGGER.error('Hub not found at http://%s:%d, check configuration',
                           self._host, self._port)
-        elif response.status in range(500, 600):
+        elif status in range(500, 600):
             _LOGGER.error('Hub returned a server error')
             _LOGGER.error('Restart the Hub and try again')
         else:

insteonplm/devices/__init__.py

@@ -1,9 +1,8 @@
 """Insteon Device Classes."""
 import asyncio
 import async_timeout
-import collections
+from collections import namedtuple
 from concurrent.futures import CancelledError
-from contextlib import suppress
 import datetime
 from enum import Enum
 import logging
@@ -20,12 +19,15 @@
     COMMAND_GET_INSTEON_ENGINE_VERSION_0X0D_0X00,
     COMMAND_PING_0X0F_0X00,
     COMMAND_EXTENDED_READ_WRITE_ALDB_0X2F_0X00,
+    MESSAGE_ACK,
+    MESSAGE_TYPE_BROADCAST_MESSAGE,
     MESSAGE_TYPE_DIRECT_MESSAGE,
     MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0,
     MESSAGE_STANDARD_MESSAGE_RECEIVED_0X50,
     MESSAGE_EXTENDED_MESSAGE_RECEIVED_0X51
 )
 from insteonplm.messagecallback import MessageCallback
+from insteonplm.messages.allLinkComplete import AllLinkComplete
 from insteonplm.messages.extendedReceive import ExtendedReceive
 from insteonplm.messages.standardReceive import StandardReceive
 from insteonplm.messages.extendedSend import ExtendedSend
@@ -41,6 +43,10 @@
 ALDB_ALL_RECORD_RETRIES = 5
 
 
+LoadAction = namedtuple('LoadAction', 'mem_addr rec_count retries')
+DeviceInfo = namedtuple('DeviceInfo', 'address cat subcat firmware')
+
+
 def create(plm, address, cat, subcat, firmware=None):
     """Create a device from device info data."""
     from insteonplm.devices.ipdb import IPDB
@@ -74,7 +80,7 @@ class Device(object):
     def __init__(self, plm, address, cat, subcat, product_key=0x00,
                  description='', model=''):
         """Initialize the Device class."""
-        self.log = logging.getLogger(__name__)
+        self.log = logging.getLogger()
 
         self._plm = plm
 
@@ -99,7 +105,9 @@ def __init__(self, plm, address, cat, subcat, product_key=0x00,
         self._recent_messages = asyncio.Queue(loop=self._plm.loop)
         self._send_msg_queue = asyncio.Queue(loop=self._plm.loop)
         self._directACK_received_queue = asyncio.Queue(loop=self._plm.loop)
+        self._device_info_queue = asyncio.Queue(loop=self._plm.loop)
         self._send_msg_lock = asyncio.Lock(loop=self._plm.loop)
+        self._device_info_retries = 0
 
         self._register_messages()
 
@@ -172,6 +180,10 @@ def async_refresh_state(self):
 
     def id_request(self):
         """Request a device ID from a device."""
+        import inspect
+        curframe = inspect.currentframe()
+        calframe = inspect.getouterframes(curframe, 2)
+        self.log.debug('caller name: %s', calframe[1][3])
         msg = StandardSend(self.address, COMMAND_ID_REQUEST_0X10_0X00)
         self._plm.send_msg(msg)
 
@@ -310,28 +322,176 @@ def _handle_pre_nak(self, msg):
         self.log.warning('Checking status to confirm if message was processed')
         self.async_refresh_state()
 
+    def _handle_get_device_info_ack(self, msg):
+        self.log.debug('Starting _handle_get_device_info_ack with message:')
+        self.log.debug(msg)
+        asyncio.ensure_future(self._wait_device_info(msg), loop=self._plm.loop)
+
+    def _handle_assign_to_all_link_group(self, msg):
+        cat = 0xff
+        subcat = 0
+        product_key = 0
+        if msg.code == StandardReceive.code and msg.flags.isBroadcast:
+            self.log.debug('Received broadcast ALDB group assigment request.')
+            cat = msg.targetLow
+            subcat = msg.targetMed
+            product_key = msg.targetHi
+            self._add_device_from_prod_data(msg.address, cat,
+                                            subcat, product_key)
+        elif msg.code == AllLinkComplete.code:
+            if msg.linkcode in [0, 1, 3]:
+                self.log.debug('Received ALDB complete response.')
+                cat = msg.category
+                subcat = msg.subcategory
+                product_key = msg.firmware
+                self._add_device_from_prod_data(msg.address, cat,
+                                                subcat, product_key)
+                self._update_aldb_records(msg.linkcode, msg.address, msg.group)
+            else:
+                self.log.debug('Received ALDB delete response.')
+                self._update_aldb_records(msg.linkcode, msg.address, msg.group)
+
+    def _add_device_from_prod_data(self, address, cat, subcat, product_key):
+        self.log.debug('Received Device ID with address: %s  '
+                       'cat: 0x%x  subcat: 0x%x', address, cat, subcat)
+        device = self._plm.devices.create_device_from_category(
+            self._plm, address, cat, subcat, product_key)
+        if device:
+            if not self._plm.devices[device.id]:
+                self._plm.devices[device.id] = device
+                self.log.info('Device with id %s added to device list.',
+                              device.id)
+            self.log.info('Total Devices Found: %d', len(self._plm.devices))
+            self._plm.aldb_device_handled(self._address)
+            self._plm.devices.save_device_info()
+        else:
+            self.log.error('Device %s not in the IPDB.',
+                           Address(address).human)
+            self._plm.device_not_active(self.address)
+
+    def _update_aldb_records(self, linkcode, address, group):
+        """Refresh the IM and device ALDB records."""
+        device = self.devices[Address(address).id]
+        if device and device.aldb.status in [ALDBStatus.LOADED,
+                                             ALDBStatus.PARTIAL]:
+            for mem_addr in device.aldb:
+                rec = device.aldb[mem_addr]
+                if linkcode in [0, 1, 3]:
+                    if rec.control_flags.is_high_water_mark:
+                        self.log.info('Removing HWM recordd %04x', mem_addr)
+                        device.aldb.pop(mem_addr)
+                    elif not rec.control_flags.is_in_use:
+                        self.log.info('Removing not in use recordd %04x',
+                                      mem_addr)
+                        device.aldb.pop(mem_addr)
+                else:
+                    if rec.address == self.address and rec.group == group:
+                        self.log.info('Removing record %04x with addr %s and '
+                                      'group %d', mem_addr, rec.address,
+                                      rec.group)
+                        device.aldb.pop(mem_addr)
+            device.read_aldb()
+            device.aldb.add_loaded_callback(self._refresh_aldb())
+
+    @asyncio.coroutine
+    def _wait_device_info(self, msg):
+        self.log.debug('Starting _wait_device_info for device %s in %s',
+                       msg.address.human, self._address.human)
+        try:
+            with async_timeout.timeout(6):
+                device_info_msg = yield from self._device_info_queue.get()
+                self.log.debug('_wait_device_info got device_id message %s',
+                               device_info_msg)
+        except asyncio.TimeoutError:
+            self.log.debug('_wait_device_info timeout reached for message %s in %s',
+                           msg.address.human, self._address.human)
+            if self._device_info_retries < 5:
+                self._device_info_retries += 1
+                self.log.debug('Device %s id_request retry %d',
+                               self.address.human, self._device_info_retries)
+                self.id_request()
+            else:
+                self.log.warning('Device %s did not respond to an ID request',
+                                 self.address.human)
+                self.log.warning('Use a device override to define the device '
+                                 'type')
+                self._plm.device_not_active(self.address)
+            return
+        self._device_info_retries = 0
+        address = device_info_msg.address
+        cat = device_info_msg.targetLow
+        subcat = device_info_msg.targetMed
+        product_key = device_info_msg.targetHi
+        self._add_device_from_prod_data(address, cat, subcat, product_key)
+
+    def _handle_device_info_response(self, msg):
+        self.log.debug('Got device_id for %s in %s', msg.address.human,
+                       self._address.human)
+        self._device_info_queue.put_nowait(msg)
+
+    def _handle_all_link_complete(self, msg):
+        last_record = None
+        for mem_addr in self.aldb:
+            aldb_rec = self.aldb[mem_addr]
+            if aldb_rec.control_flags.is_high_water_mark:
+                last_record = mem_addr
+        if last_record:
+            self.aldb.pop(last_record)
+        self.read_aldb()
+
     def _register_messages(self):
-            ext_msg_aldb_record = ExtendedReceive.template(
-                address=self._address,
-                commandtuple=COMMAND_EXTENDED_READ_WRITE_ALDB_0X2F_0X00,
-                userdata=Userdata.template({'d2': 1}),
-                flags=MessageFlags.template(
-                    messageType=MESSAGE_TYPE_DIRECT_MESSAGE,
-                    extended=1))
-            std_msg_pre_nak = StandardReceive.template(
-                flags=MessageFlags.template(
-                    messageType=MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0),
-                cmd2=0xfc)
-            ext_msg_pre_nak = ExtendedReceive.template(
-                flags=MessageFlags.template(
-                    messageType=MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0),
-                cmd2=0xfc)
-            self._message_callbacks.add(ext_msg_aldb_record,
-                                        self._handle_aldb_record_received)
-            self._message_callbacks.add(std_msg_pre_nak,
-                                        self._handle_pre_nak)
-            self._message_callbacks.add(ext_msg_pre_nak,
-                                        self._handle_pre_nak)
+        self.log.debug('Registering messages for %s', self._address.human)
+        std_device_info_request_ack = StandardSend.template(
+            address=self._address,
+            commandtuple=COMMAND_ID_REQUEST_0X10_0X00,
+            acknak=MESSAGE_ACK)
+        self.log.debug('ID ACK: %s', std_device_info_request_ack)
+        self._message_callbacks.add(std_device_info_request_ack,
+                                    self._handle_get_device_info_ack)
+
+        std_device_info_response = StandardReceive.template(
+            address=self._address,
+            commandtuple=COMMAND_ASSIGN_TO_ALL_LINK_GROUP_0X01_NONE,
+            flags=MessageFlags.template(
+                messageType=MESSAGE_TYPE_BROADCAST_MESSAGE))
+        self._message_callbacks.add(std_device_info_response,
+                                    self._handle_device_info_response)
+
+        std_assign_all_link = StandardReceive.template(
+            address=self._address,
+            commandtuple=COMMAND_ASSIGN_TO_ALL_LINK_GROUP_0X01_NONE,
+            flags=MessageFlags.template(MESSAGE_TYPE_DIRECT_MESSAGE))
+        self._message_callbacks.add(std_assign_all_link,
+                                    self._handle_assign_to_all_link_group)
+
+        ext_msg_aldb_record = ExtendedReceive.template(
+            address=self._address,
+            commandtuple=COMMAND_EXTENDED_READ_WRITE_ALDB_0X2F_0X00,
+            userdata=Userdata.template({'d2': 1}),
+            flags=MessageFlags.template(
+                messageType=MESSAGE_TYPE_DIRECT_MESSAGE,
+                extended=1))
+        self._message_callbacks.add(ext_msg_aldb_record,
+                                    self._handle_aldb_record_received)
+
+        std_msg_pre_nak = StandardReceive.template(
+            flags=MessageFlags.template(
+                messageType=MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0),
+            cmd2=0xfc)
+        self._message_callbacks.add(std_msg_pre_nak,
+                                    self._handle_pre_nak)
+
+        ext_msg_pre_nak = ExtendedReceive.template(
+            flags=MessageFlags.template(
+                messageType=MESSAGE_FLAG_DIRECT_MESSAGE_NAK_0XA0),
+            cmd2=0xfc)
+        self._message_callbacks.add(ext_msg_pre_nak,
+                                    self._handle_pre_nak)
+
+        template_all_link_complete = AllLinkComplete(None, None, None,
+                                                     None, None, None)
+        self._message_callbacks.add(template_all_link_complete,
+                                    self._handle_all_link_complete)
 
     # Send / Receive message processing
     def receive_message(self, msg):
@@ -419,7 +579,6 @@ def _send_msg(self, msg, callback=None, on_timeout=False):
         asyncio.ensure_future(self._process_send_queue(), loop=self._plm.loop)
         self.log.debug('Ending Device._send_msg')
 
-
     @asyncio.coroutine
     def _process_send_queue(self):
         self.log.debug('Starting Device._process_send_queue')
@@ -432,8 +591,8 @@ def _process_send_queue(self):
         if callback:
             self._sent_msg_wait_for_directACK = msg_info
         self._plm.send_msg(msg)
-        #if self._send_msg_lock.locked():
-        #    self._send_msg_lock.release()
+        # if self._send_msg_lock.locked():
+        #     self._send_msg_lock.release()
         self.log.debug('Ending Device._process_send_queue')
 
     @asyncio.coroutine
@@ -807,9 +966,6 @@ class ALDBVersion(Enum):
     v2cs = 20
 
 
-LoadAction = collections.namedtuple('LoadAction', 'mem_addr rec_count retries')
-
-
 class ALDB(object):
     """Represents a device All-Link database."""
 

insteonplm/devices/switchedLightingControl.py

@@ -6,9 +6,6 @@
                                      OnOffKeypadA,
                                      OnOffKeypad,
                                      OnOffKeypadLed)
-from insteonplm.messages.userdata import Userdata
-from insteonplm.messages.extendedSend import ExtendedSend
-from insteonplm.constants import COMMAND_EXTENDED_GET_SET_0X2E_0X00
 
 
 class SwitchedLightingControl(Device):