Postpone "Z-wave not ready" warning (#11807)

* Release worker thread while waiting for Z-wave startup

* Increase zwave startup timeout

* Adjust test

* Use asyncio.sleep in _check_awaked

* Remove lint

* Name loop parameter

homeassistant/components/zwave/__init__.py

@@ -7,7 +7,6 @@ https://home-assistant.io/components/zwave/
 import asyncio
 import copy
 import logging
-import time
 from pprint import pprint
 
 import voluptuous as vol
@@ -22,6 +21,7 @@ from homeassistant.const import (
 from homeassistant.helpers.entity_values import EntityValues
 from homeassistant.helpers.event import track_time_change
 from homeassistant.util import convert, slugify
+import homeassistant.util.dt as dt_util
 import homeassistant.helpers.config_validation as cv
 from homeassistant.helpers.dispatcher import (
     async_dispatcher_connect, async_dispatcher_send)
@@ -592,25 +592,40 @@ def setup(hass, config):
         network.start()
         hass.bus.fire(const.EVENT_NETWORK_START)
 
-        # Need to be in STATE_AWAKED before talking to nodes.
+        @asyncio.coroutine
-        # Wait up to NETWORK_READY_WAIT_SECS seconds for the zwave network
+        def _check_awaked():
-        # to be ready.
+            """Wait for Z-wave awaked state (or timeout) and finalize start."""
-        for i in range(const.NETWORK_READY_WAIT_SECS):
             _LOGGER.debug(
                 "network state: %d %s", network.state,
                 network.state_str)
-            if network.state >= network.STATE_AWAKED:
-                _LOGGER.info("Z-Wave ready after %d seconds", i)
-                break
-            time.sleep(1)
-        else:
-            _LOGGER.warning(
-                "zwave not ready after %d seconds, continuing anyway",
-                const.NETWORK_READY_WAIT_SECS)
-            _LOGGER.info(
-                "final network state: %d %s", network.state,
-                network.state_str)
 
+            start_time = dt_util.utcnow()
+            while True:
+                waited = int((dt_util.utcnow()-start_time).total_seconds())
+
+                if network.state >= network.STATE_AWAKED:
+                    # Need to be in STATE_AWAKED before talking to nodes.
+                    _LOGGER.info("Z-Wave ready after %d seconds", waited)
+                    break
+                elif waited >= const.NETWORK_READY_WAIT_SECS:
+                    # Wait up to NETWORK_READY_WAIT_SECS seconds for the Z-Wave
+                    # network to be ready.
+                    _LOGGER.warning(
+                        "Z-Wave not ready after %d seconds, continuing anyway",
+                        waited)
+                    _LOGGER.info(
+                        "final network state: %d %s", network.state,
+                        network.state_str)
+                    break
+                else:
+                    yield from asyncio.sleep(1, loop=hass.loop)
+
+            hass.async_add_job(_finalize_start)
+
+        hass.add_job(_check_awaked)
+
+    def _finalize_start():
+        """Perform final initializations after Z-Wave network is awaked."""
         polling_interval = convert(
             config[DOMAIN].get(CONF_POLLING_INTERVAL), int)
         if polling_interval is not None:

homeassistant/components/zwave/const.py

@@ -20,7 +20,7 @@ ATTR_CONFIG_VALUE = "value"
 ATTR_POLL_INTENSITY = "poll_intensity"
 ATTR_VALUE_INDEX = "value_index"
 ATTR_VALUE_INSTANCE = "value_instance"
-NETWORK_READY_WAIT_SECS = 30
+NETWORK_READY_WAIT_SECS = 300
 
 DISCOVERY_DEVICE = 'device'
 

tests/components/zwave/test_init.py

@@ -154,18 +154,31 @@ def test_zwave_ready_wait(hass, mock_openzwave):
     yield from async_setup_component(hass, 'zwave', {'zwave': {}})
     yield from hass.async_block_till_done()
 
-    with patch.object(zwave.time, 'sleep') as mock_sleep:
+    sleeps = []
-        with patch.object(zwave, '_LOGGER') as mock_logger:
-            hass.data[DATA_NETWORK].state = MockNetwork.STATE_STARTED
-            hass.bus.async_fire(EVENT_HOMEASSISTANT_START)
-            yield from hass.async_block_till_done()
 
-            assert mock_sleep.called
+    def utcnow():
-            assert len(mock_sleep.mock_calls) == const.NETWORK_READY_WAIT_SECS
+        return datetime.fromtimestamp(len(sleeps))
-            assert mock_logger.warning.called
+
-            assert len(mock_logger.warning.mock_calls) == 1
+    asyncio_sleep = asyncio.sleep
-            assert mock_logger.warning.mock_calls[0][1][1] == \
+
-                const.NETWORK_READY_WAIT_SECS
+    @asyncio.coroutine
+    def sleep(duration, loop):
+        if duration > 0:
+            sleeps.append(duration)
+        yield from asyncio_sleep(0, loop=loop)
+
+    with patch('homeassistant.components.zwave.dt_util.utcnow', new=utcnow):
+        with patch('asyncio.sleep', new=sleep):
+            with patch.object(zwave, '_LOGGER') as mock_logger:
+                hass.data[DATA_NETWORK].state = MockNetwork.STATE_STARTED
+                hass.bus.async_fire(EVENT_HOMEASSISTANT_START)
+                yield from hass.async_block_till_done()
+
+                assert len(sleeps) == const.NETWORK_READY_WAIT_SECS
+                assert mock_logger.warning.called
+                assert len(mock_logger.warning.mock_calls) == 1
+                assert mock_logger.warning.mock_calls[0][1][1] == \
+                    const.NETWORK_READY_WAIT_SECS
 
 
 @asyncio.coroutine