Hub general exception (#167)

* Restart on general exception and log error better

* Bump version to 0.16.2

* Improve IM closing process

* Send ACK and Direct ACk to complete processing

Author: teharris1

insteonplm/__init__.py

@@ -485,8 +485,8 @@ async def _ensure_reader(self):
                 _LOGGER.error('Reconnect to Hub (TimeoutError)')
                 await self._stop_reader(True)
             except Exception as e:
-                _LOGGER.debug('Stop reading due to %s', str(e))
-                await self._stop_reader(False)
+                _LOGGER.debug('Restarting reading due to %s', str(e))
+                await self._stop_reader(True)
         _LOGGER.info('Insteon Hub reader stopped')
         return
 

insteonplm/plm.py

@@ -315,10 +315,8 @@ async def pause_writing(self):
         """Pause writing."""
         self._restart_writer = False
         if self._writer_task:
-            self._writer_task.remove_done_callback(self.restart_writing)
-            self._writer_task.cancel()
-            await self._writer_task
-            await asyncio.sleep(0, loop=self._loop)
+            self._send_queue.put_nowait(None)
+        await asyncio.sleep(.1)
 
     # pylint: disable=unused-argument
     def restart_writing(self, task=None):
@@ -412,9 +410,12 @@ async def _get_message_from_send_queue(self):
         await self._write_transport_lock.acquire()
         while self._restart_writer:
             # wait for an item from the queue
+            msg_info = await self._send_queue.get()
+            if msg_info is None:
+                self._restart_writer = False
+                return
+            message_sent = False
             try:
-                msg_info = await self._send_queue.get()
-                message_sent = False
                 while not message_sent:
                     message_sent = await self._write_message(msg_info)
                 await asyncio.sleep(msg_info.wait_timeout, loop=self._loop)
@@ -429,6 +430,7 @@ async def _get_message_from_send_queue(self):
             except Exception as e:
                 _LOGGER.error('Restarting Insteon Modem writer due to %s',
                               str(e))
+                _LOGGER.error('MSG: %s', str(msg_info.msg))
                 self._restart_writer = True
         if self._write_transport_lock.locked():
             self._write_transport_lock.release()

setup.py

@@ -11,7 +11,7 @@ def readme():
 
 setup(
     name='insteonplm',
-    version='0.16.1',
+    version='0.16.2',
     author='David McNett',
     author_email='nugget@macnugget.org',
     url='https://github.com/nugget/python-insteonplm',

tests/test_plm.py

@@ -6,6 +6,7 @@
 from insteonplm.constants import (COMMAND_LIGHT_ON_0X11_NONE,
                                   COMMAND_LIGHT_OFF_0X13_0X00,
                                   MESSAGE_FLAG_BROADCAST_0X80,
+                                  MESSAGE_FLAG_DIRECT_MESSAGE_ACK_0X20,
                                   COMMAND_ID_REQUEST_0X10_0X00,
                                   COMMAND_LIGHT_STATUS_REQUEST_0X19_0X00,
                                   MESSAGE_NAK,
@@ -195,15 +196,34 @@ def async_light_on_level_callback(device_id, state, value):
                        acknak=MESSAGE_ACK)
     plm.data_received(msg.bytes)
 
+    # Direct ACK of off message
+    msg = StandardReceive(
+        address='4d5e6f', target='010b00',
+        commandtuple=COMMAND_LIGHT_OFF_0X13_0X00,
+        flags=MESSAGE_FLAG_DIRECT_MESSAGE_ACK_0X20)
+    plm.data_received(msg.bytes)
+
     # Test that the second SET_LEVEL command is sent
     msg = StandardSend('4d5e6f', COMMAND_LIGHT_ON_0X11_NONE, cmd2=0xbb)
     cmd_sent = await wait_for_plm_command(plm, msg, loop)
     if not cmd_sent:
         assert False
 
+    # ACK the SET_LEVEL command and let the Direct ACK message expire
+    msg = StandardSend('4d5e6f', COMMAND_LIGHT_ON_0X11_NONE, cmd2=0xbb,
+                       acknak=MESSAGE_ACK)
+    plm.data_received(msg.bytes)
+    
+    msg = StandardReceive(
+        address='4d5e6f', target='010b00',
+        commandtuple=COMMAND_LIGHT_ON_0X11_NONE,
+        cmd2=0xbb,
+        flags=MESSAGE_FLAG_DIRECT_MESSAGE_ACK_0X20)
+    plm.data_received(msg.bytes)
+
     await plm.close()
     _LOGGER.error('PLM closed in test_plm')
-    await asyncio.sleep(0, loop=loop)
+    await asyncio.sleep(.1, loop=loop)
     open_tasks = asyncio.Task.all_tasks(loop=loop)
     for task in open_tasks:
         if hasattr(task, 'name'):
@@ -215,6 +235,7 @@ def async_light_on_level_callback(device_id, state, value):
 # pylint: disable=too-many-statements
 async def do_plm_x10(loop):
     """Asyncio coroutine to test the PLM X10 message handling."""
+    _LOGGER.setLevel(logging.DEBUG)
     _LOGGER.info('Connecting to Insteon PLM')
 
     # pylint: disable=not-an-iterable
@@ -269,9 +290,12 @@ async def do_plm_x10(loop):
     await asyncio.sleep(.1, loop=loop)
     assert cb.callbackvalue1 == 0x00
 
+    _LOGGER.info('Close PLM')
+    _LOGGER.info('_________')
+
     await plm.close()
     _LOGGER.error('PLM closed in test_x10')
-    await asyncio.sleep(0, loop=loop)
+    await asyncio.sleep(.1, loop=loop)
     open_tasks = asyncio.Task.all_tasks(loop=loop)
     for task in open_tasks:
         if hasattr(task, 'name'):
@@ -310,3 +334,7 @@ def test_plm_x10():
             _LOGGER.error('Task: %s', task)
         if not task.done():
             loop.run_until_complete(task)
+
+
+if __name__ == '__main__':
+    test_plm()